Severe Server Saturation when enabling with Locale Module is active
| Project: | Playlist (toolkit, modules) |
| Version: | 4.7.x-1.x-dev |
| Component: | Code |
| Category: | bug report |
| Priority: | critical |
| Assigned: | Unassigned |
| Status: | active |
Jump to:
I lost a whole afternoon dealing with this and then took the time to replicate it.
This is a severe bug that will saturate both the memory and the cpu of the server when activating the audio_playlist module if the locale module is active.
Here is my recount of the issues:
I enabled the playlist module and no problem.
I then enabled the audio_playlist module and the modules page never reloaded. I went to look at the server and found the server load and memory used increasing quickly.
Less than 2 min. after I clicked the button on the modules page to activate the module, my server load had jumped to 38.03 cpus (normal load is below 1 with some pics during the day that reach sometimes 7-9). Memory had risen to 88.2% from the normal less than 50%:
Server Load 38.03 (2 cpus)
Memory Used 88.2 %
And the modules page still did not reload.
I then looked at my MySQL processes and found a growing number of processes, when normally you only get to see one or two or three. Here is a copy (I have renamed the db and user names of course). Although I have about a dozen drupal implementations running as multisite, the only processes shown were from the site where I was trying to active audio_playlist:
+------+------------------+-----------+-------------------+---------+------+--------------+------------------------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+------+------------------+-----------+-------------------+---------+------+--------------+------------------------------------------------------------------------------------------------------+
| 7004 | *database_user* | localhost | *mysql_database* | Query | 1 | Sending data | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7006 | *database_user* | localhost | *mysql_database* | Query | 0 | Sending data | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7008 | *database_user* | localhost | *mysql_database* | Query | 1 | Sending data | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7013 | *database_user* | localhost | *mysql_database* | Query | 0 | Sending data | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7014 | *database_user* | localhost | *mysql_database* | Query | 0 | Sending data | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7019 | *database_user* | localhost | *mysql_database* | Query | 0 | Sending data | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7022 | *database_user* | localhost | *mysql_database* | Query | 0 | Sending data | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7023 | root | localhost | | Query | 0 | | show processlist |
+------+------------------+-----------+-------------------+---------+------+--------------+------------------------------------------------------------------------------------------------------+A couple of minutes later, server load and memory usage were even higher and there were even more processes:
Server Load 49.07 (2 cpus)
Memory Used 90.7 %
Ignore the gallery processes, they appear most likely because with the server saturated they must have had a hard time completing...
+------+------------------+-----------+-------------------+---------+------+----------------+------------------------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+------+------------------+-----------+-------------------+---------+------+----------------+------------------------------------------------------------------------------------------------------+
| 7004 | *database_user* | localhost | *mysql_database* | Query | 0 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7008 | *database_user* | localhost | *mysql_database* | Query | 0 | Opening tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7013 | *database_user* | localhost | *mysql_database* | Sleep | 82 | | |
| 7019 | *database_user* | localhost | *mysql_database* | Query | 0 | closing tables | SELECT COUNT(*) FROM comments WHERE nid = 652 AND status = 0 |
| 7022 | *database_user* | localhost | *mysql_database* | Query | 0 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7025 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7026 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7027 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7028 | *database_user* | localhost | *mysql_database* | Sleep | 1 | | |
| 7029 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7030 | *database_user* | localhost | *mysql_database* | Sleep | 10 | | |
| 7031 | *database_user* | localhost | *mysql_database* | Query | 1 | Opening tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7033 | *database_user* | localhost | *mysql_database* | Query | 0 | Opening tables | SELECT dst FROM url_alias WHERE src = 'user/login' |
| 7035 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7052 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7057 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7061 | *database_user* | localhost | *mysql_database* | Query | 2 | closing tables | SELECT last_comment_timestamp, last_comment_name, comment_count FROM node_comment_statistics WHERE n |
| 7066 | *database_user* | localhost | *mysql_database* | Sleep | 5 | | |
| 7072 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Sleep | 22 | | |
| 7073 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7074 | *database_user* | localhost | *mysql_database* | Query | 0 | Opening tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7075 | *database_user* | localhost | *mysql_database* | Query | 1 | Opening tables | SELECT src FROM url_alias WHERE dst = 'node' |
| 7076 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7077 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Sleep | 25 | | |
| 7079 | *database_user* | localhost | *mysql_database* | Query | 0 | Opening tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7082 | *database_user* | localhost | *mysql_database* | Sleep | 5 | | |
| 7084 | *database_user* | localhost | *mysql_database* | Sleep | 22 | | |
| 7085 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Sleep | 13 | | |
| 7088 | *database_user* | localhost | *mysql_database* | Sleep | 10 | | |
| 7089 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Sleep | 20 | | |
| 7090 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Sleep | 4 | | |
| 7091 | *database_user* | localhost | *mysql_database* | Query | 1 | closing tables | SELECT s.lid, t.translation FROM locales_source s INNER JOIN locales_target t ON s.lid = t.lid WHERE |
| 7092 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Sleep | 10 | | |
| 7095 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Sleep | 7 | | |
| 7096 | *database_user* | localhost | *mysql_database* | Query | 0 | closing tables | UPDATE video SET play_counter = play_counter + 1 where vid = 595 |
| 7100 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Sleep | 2 | | |
| 7102 | *database_user* | localhost | *mysql_database* | Query | 1 | Opening tables | SELECT * FROM access WHERE status = 0 AND type = 'host' AND LOWER('200.79.253.108') LIKE LOWER(mask) |
| 7103 | *database_user* | localhost | *mysql_database* | Query | 3 | closing tables | SELECT name, filename, throttle, bootstrap FROM system WHERE type = 'module' AND status = 1 ORDER BY |
| 7104 | *database_user* | localhost | *mysql_database* | Query | 3 | closing tables | SELECT u.* FROM users u WHERE u.uid = 0 |
| 7105 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Query | 5 | Opening tables | SELECT
g2_Group.g_id,
g2_Group.g_groupName
FROM
|
| 7106 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Query | 1 | Opening tables | SELECT g2_ImageBlockCacheMap.g_itemId FROM g2_ImageBlockCacheMap LEFT JOIN g2_ImageBlockDisabledMap |
| 7107 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Query | 1 | closing tables | SELECT g2_ExternalIdMap.g_entityId FROM g2_ExternalIdMap
WHERE g2_ExternalIdMap.g_externalId = '0' |
| 7108 | rdvp_drupaluser | localhost | rdvp_drupaldb | Query | 1 | Opening tables | SELECT u.*, s.* FROM users u INNER JOIN sessions s ON u.uid = s.uid WHERE s.sid = '38f63894d2fa750db |
| 7109 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Query | 1 | Opening tables | SELECT
g2_Group.g_id,
g2_Group.g_groupName
FROM
|
| 7110 | *gallery_dbuser* | localhost | *gallery_mysqldb* | Query | 1 | Opening tables | SELECT
g2_Group.g_id,
g2_Group.g_groupName
FROM
|
| 7112 | root | localhost | | Query | 0 | | show processlist |
+------+------------------+-----------+-------------------+---------+------+----------------+------------------------------------------------------------------------------------------------------+The first time this happened, server load went all the way up to 324 CPUs (from a normal less than 2) and memory usage reached 98% and the processes listed kept growing.
Since I wasn't sure what was happening, I manually disabled the playlist and audio_playlist module in the system table and reset the server. Everything was back to normal. I then disabled the locale module and emptied its tables.
I re-enabled the playlist and audio_playlist modules and they worked beautiful. I created my playlist and was enjoying it peacefully until I remembered that my site is a spanish-speaking community and I had to re-enable the locale module for the spanish translation to show.
In order to be careful, I disabled the playlist and audio_playlist modules and un-published the playlist I had created.
I re-enabled the locale module and verified that its tables were empty. I then downloaded a fresh translation from the Drupal website.
All is good so far.
I then re-enabled the playlist module. No problem.
But when I re-enabled the audio_playlist module, the same problem as before surfaced...
The modules page never reloaded, so whatever processes where started by activating the module were not being completed. I looked at my server load and memory usage and they were starting to climb.
But this time I knew what to do.
Restart MySQL, Restart Apache...
And voila, everything works. It took the server a while to shake off the saturation (with server load still above 2), so I did a full reboot and it came fresh with a server load of 0.40.
I republished my playlist and it works like a charm.
The problem seems to be somewhere in the processes that take place when activating the audio_playlist module, since it works fine after killing the rogue processes.
Regards and kudos on such and amazing module.
If you want some more feedback, let me know
Here's Apache Status, 20min. after rebooting the server and while listening to my playlist:
Server Version: Apache/1.3.36 (Unix) mod_auth_passthrough/1.8 mod_log_bytes/1.2 mod_bwlimited/1.4 PHP/4.4.2 FrontPage/5.0.2.2635.SR1.2 mod_ssl/2.8.27 OpenSSL/0.9.7a
Server Built: May 30 2006 11:30:52
Current Time: Friday, 15-Sep-2006 20:50:12 AST
Restart Time: Friday, 15-Sep-2006 20:30:15 AST
Parent Server Generation: 0
Server uptime: 19 minutes 57 seconds
Total accesses: 5144 - Total Traffic: 35.1 MB
CPU Usage: u129.56 s5.01 cu0 cs0 - 11.2% CPU load
4.3 requests/sec - 30.1 kB/second - 7.0 kB/request
20 requests currently being processed, 16 idle serversMySQL is 4.1.21
As I was finishing this post, the server load suddenly skyrocketed to 50 CPUs and memory to 89.8%... :-(
I'm restarting and disabling the modules...
:-( I liked the playlist...
I'll keep a close watch on the server in case the situation happens again with the modules disabled and it's something else...
Regards,
Carlos.
#1
Thanks for such a detailed report...I will try and take a look at this. I have no ideas why this would happen off the top of my head. Anybody with any ideas, or similar problems, please post here...
#2
Any news on this one? I'm running into the same problem. Turn on the locale and playlist and I see a huge spike in cpu activity for mysql when a page loads. Turn off local or playlist and things go back to normal.
#3
Be careful what Drupal functions you use in the global context. When modules are include()d by Drupal, the locale isn't initialized yet, which in turn breaks things when using the
t()-function. This means you can't uset()(or any function that callst()) outside a Drupal hook. This behavior is decribed in full length here.The current playlist module, however, doesn't seem to contain such code (only checked the first couple of lines, though).
Carlos & Scott, did you do any modifications to playlist? For example, for a multilingual site, I would add a
t()around thedefine()at the top of audio_playlist.module to get the playlist name properly translated:// Use a settings variable to control the readable name of the node type.define("AUDIO_PLAYLIST_NAME", variable_get('audio_playlist_name', 'audio playlist'), true);
This would be an example for how to break things. However, this can be easily circumvented by moving the code into an early executed hook function, like
hook_init()(for Drupal 4.7.2+) orhook_menu()(on or before 4.7.2).Generally speaking, you shouldn't execute any Drupal-related code in the global context.
@zirafa
Please consider moving the define into a hook function.
Hope this helps a bit, though no definitive solution...
--
Stefan Kudwien
http://www.unleashedmind.com
#4
Stefan, you were completely right. The code in the latest 4.7 audio_playlist.module looks like this:
// Use a settings variable to control the readable name of the node type.define("AUDIO_PLAYLIST_NAME", variable_get('audio_playlist_name', t('audio playlist')), true);
Removing the t() from around 'audio playlist' solved all my problems. I guess this fix is already checked into CVS, but it didn't seem to make it into the 4.7 release.
Thanks for the help.