updating the simplenews_mail_spool status = 2 is SUPER slow [#1260264]

I am watching my newsletters progress and as I watch them being sent I am running this query:
SELECT * FROM simplenews_mail_spool s WHERE status = 2;
I run this and update it 1/second and some times 5 will show up and some times 0 will show up. Sometimes 0 will show up for several seconds. I don't think this is how it should behave, though I could be mistaken.

Any ideas on how to troubleshoot/work through this.

Comments

Comment #1

miro_dietiker

Switzerland

commented 26 August 2011 at 06:29

Status:

Active

» Postponed (maintainer needs more info)

An index for status might be missing to make it query faster. However i cannot follow you what's the issue actually.

Comment #2

lilott8 commented 26 August 2011 at 13:47

It's not an index thing. The query for status = 2 finishes in .0013 seconds.

The actual issue at hand isn't that query, it's the speed at which simplenews is sending emails.

I would assume that pulling from mail_spool and loading the node, sending the mail and updating status wouldn't take multiple seconds. I can watch the speed at which simplenews is sending the emails and it's not that quick.

As far as I can tell the process is this:

select * from simplenews_mail_spool
do some formatting/create header
load the node
loop:
if node != cached, load it & cache it
start sending mail
update status to 2 on successful send
continue loop
when cron done or limit reached, delete * from simplenews_mail_spool where status = 2

With the way the code is written it looks like it should rocket through them. But as I watch simplenews process the spool, it goes slower than I would think it should.

Comment #3

miro_dietiker

Switzerland

commented 26 August 2011 at 17:01

I can only say that simplenews is rocket fast.
I have absolutely no idea what you do to make it so slow.

Cannot help you with the information provided.

Comment #4

lilott8 commented 26 August 2011 at 18:33

Ok,

I'll give you anything you ask for to get this resolved. Just let me know!

Server Specs:

Webserver: FC 14; 4 Gigs Ram; 2 CPUs; Apache 2.2.17; php 5.3.6; I am using the smtp/mime mail modules
Mysql Server: FC 13; 4 Gigs Ram; 2 CPUs; MySQL 5.1.47
SMTP server: FC 13; 2 Gigs Ram; 2 CPUs
Other: My crontab is set to 2 minutes using wget; My simplenews is set to 100/cron; My simplenews barely has enough time to send all 100 in 2 minutes; My logs say that I sent ~100 emails in ~8 seconds***; My php timeout is set at 120

Any other additional information I will gladly provide. I really want this to be solved. Any place to even start troubleshooting would be great.

I've tested extensively the cron/simplenews send/php configuration timeout and this is the best I could get it.

***Using math I should be able to send out roughly 1500 emails every 2 minutes. I cannot. When I start cranking up the messengers sent my cron gets screwed up and people start receiving > 8 emails.

Comment #5

miro_dietiker

Switzerland

commented 26 August 2011 at 18:41

if you make php send out more mails, php uses more memory.
if memory reaches the hard limit, cron gets even locked for some time.

You should trigger the cron more often instead of enlarging its resources. For hispeed sending, you could even build a drush script to trigger sending without much delay.

Comment #6

lilott8 commented 26 August 2011 at 19:12

But the problem is still the fact that simplenews sends out things not fast at all. Are you using SN 2.x alpha 2? Why am I not getting the same speedy results as most everyone else? :(

If i shrink the time that it sends stuff out, I will run into problems with cron again. My memory limit is set at: 256M. So I don't think that is the issue. As of writing, the script is consistently using 4MB of memory (at the end of simplenews_mail_mail).

What I'm hoping to get to is sending 2000 emails in about 10 minutes (or more).

Right now, because of the way things are performing I am looking at ~1400 in about 60 minutes.

Comment #7

simon georges commented 29 August 2011 at 10:29

It could eventually be MySQL that is slowing. Could you show us your database configuration file ?

Comment #8

lilott8 commented 29 August 2011 at 13:35

my my.conf


[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=[changed]
skip-name-resolve
#defaults-extra-file = ~/.my.cnf
#Buffers
max_connections = 2048
key_buffer_size = 256M
#this will be changed after the
#database imports are complete
#should read 1M
max_allowed_packet = 100M
table_cache = 256
sort_buffer_size = 3M
read_buffer_size = 3M
join_buffer_size = 3M
#GROUP BY && ORDER BY
read_rnd_buffer_size = 3M
max_heap_table_size = 256M
tmp_table_size = 256M

myisam_sort_buffer_size = 256M
#increase until threds_created doesn't grow anymore
thread_cache=256

query_cache_type = 1
query_cache_limit = 3M
query_cache_size = 64M

#try number of CPU's*2 for thread_concurrency
thread_concurrency = 4

# Default to using old password format for compatibility with mysql 3.x
# clients (those using the mysqlclient10 compatibility package).
old_passwords=0

# Disabling symbolic-links is recommended to prevent assorted security risks;
# to do so, uncomment this line:
symbolic-links=0
## To allow mysqld to connect to a MySQL Cluster management daemon, uncomment
# these lines and adjust the connectstring as needed.
#ndbcluster
#ndb-connectstring="nodeid=4;host=localhost:1186"
#Logging!
general_log=/var/log/mysqld/mysqld.log
log-error=/var/log/mysqld/error.log
log-bin=/var/log/mysqld/bin.log
slow_query_log=/var/log/mysqld/slow.log
expire_logs_days = 10
#Use this only to find out how queries are constructed,
#DO NOT leave on for a production site for too long
#log=/var/log/mysqld/queries.log
#Prevents users without Processlist to issue
#a SHOW DATABASES; command
#skip_show_databases=ON


#Master-slave info
#binlog-do-db=drupal
#enable me
binlog-do-db=drupal
binlog-do-db=whd
binlog-do-db=spectator
binlog-ignore-db=mysql
binlog-do-db=moodle
server-id=1
#me enabled
#relay-log = /usr/share/mysql/var/mysql-relay-bin
#relay-log-index = /usr/share/mysql/var/mysql-relay-bin.index
#log-error = /usr/share/mysql/var/mysql.err
#master-info-file = /usr/share/mysql/var/mysql-master.info
#relay-log-info-file = /usr/share/mysql/var/mysql-relay-log.info
datadir= /var/lib/mysql
#sync_binlog=1
#replicate-wild-ignore-table=drupal%.cache%
#replicate-wild-ignore-table=drupal%.watchdog%

#enable me so slave doesn't freak on error
slave-skip-errors=all

#innodb
#innodb_buffer_pool_size=320M
#innodb_log_file_size=256M
#innodb_log_buffer_size=4M
#innodb_flush_log_at_trx_commit=2
#innodb_thread_concurrency=8
#innodb_fulsh_method=O_DIRECT
#innodb_file_per_table=1
#transaction-isolation=READ-COMMITTED

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

[ndbd]
# If you are running a MySQL Cluster storage daemon (ndbd) on this machine,
# adjust its connection to the management daemon here.
# Note: ndbd init script requires this to include nodeid!
#connect-string="nodeid=2;host=localhost:1186"

[ndb_mgm]
# connection string for MySQL Cluster management tool
#connect-string="host=localhost:1186"
#
[mysqldump]
quick
max_allowed_packet= 256M

Comment #9

lilott8 commented 8 September 2011 at 15:10

anyone? Does the my.cnf help at all? Any other things I can provide to help troubleshoot this?

Comment #10

miro_dietiker

Switzerland

commented 16 September 2011 at 21:39

Are you sure, there's no other module that blocks the cron?

You can e.g. use drush to trigger cron, or use elysia_cron and separate the cron processes and gather some stats.
Then you can use debugging tools to introspect what's going on any where the delay comes from.

Meanwhile no one else reported such kind of low-speed so it must be very specific to your environment.

Comment #11

lilott8 commented 23 September 2011 at 16:52

I just attempted to run cron through drush and I get the same results. The update of the status (sending) is very sporadic and very slow. It still takes several seconds to send out several items. I will look at elysia_cron monday I think.

Comment #12

lilott8 commented 23 September 2011 at 19:12

Here is an excerpt from my syslog:


Sep 23 11:51:11 www drupal: http://www.bps101.net|1316796671|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:14 www drupal: http://www.bps101.net|1316796674|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:14 www drupal: http://www.bps101.net|1316796674|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:14 www drupal: http://www.bps101.net|1316796674|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:17 www drupal: http://www.bps101.net|1316796677|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:18 www drupal: http://www.bps101.net|1316796678|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:18 www drupal: http://www.bps101.net|1316796678|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:18 www drupal: http://www.bps101.net|1316796678|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:21 www drupal: http://www.bps101.net|1316796681|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:21 www drupal: http://www.bps101.net|1316796681|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:21 www drupal: http://www.bps101.net|1316796681|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:25 www drupal: http://www.bps101.net|1316796685|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:25 www drupal: http://www.bps101.net|1316796685|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:25 www drupal: http://www.bps101.net|1316796685|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:25 www drupal: http://www.bps101.net|1316796685|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:28 www drupal: http://www.bps101.net|1316796688|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:28 www drupal: http://www.bps101.net|1316796688|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:29 www drupal: http://www.bps101.net|1316796689|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:29 www drupal: http://www.bps101.net|1316796689|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:32 www drupal: http://www.bps101.net|1316796692|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:32 www drupal: http://www.bps101.net|1316796692|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:32 www drupal: http://www.bps101.net|1316796692|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:36 www drupal: http://www.bps101.net|1316796696|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:36 www drupal: http://www.bps101.net|1316796696|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:36 www drupal: http://www.bps101.net|1316796696|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:36 www drupal: http://www.bps101.net|1316796696|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:40 www drupal: http://www.bps101.net|1316796700|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:40 www drupal: http://www.bps101.net|1316796700|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:40 www drupal: http://www.bps101.net|1316796700|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:40 www drupal: http://www.bps101.net|1316796700|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:43 www drupal: http://www.bps101.net|1316796703|smtp|127.0.0.1|http://www.bps101.net/index.php||0||Sending mail to: [email]
Sep 23 11:51:44 www drupal: http://www.bps101.net|1316796704|simplenews|127.0.0.1|http://www.bps101.net/index.php||0||100 emails sent in 1.6 seconds, 0 failed sending.
Sep 23 11:51:44 www drupal: http://www.bps101.net|1316796704|cron|127.0.0.1|http://www.bps101.net/index.php||0||Cron run completed.

You can see from the timestamps that it's not fluidly sending these out. And the end it says that it sent 100 emails/1.6 seconds. Which I believe is a lie.

Comment #13

lilott8 commented 24 October 2011 at 16:28

Status:

Postponed (maintainer needs more info)

» Closed (fixed)

I have discovered that this may have been a MTA issue. We have migrated to postfix from exim and the mail is moving MUCH faster. I now have my cron running 200 emails every 2 minutes. I will be testing with higher numbers this week. I thank you for your time in looking into this.

Comment #14

simon georges commented 24 October 2011 at 19:51

Status:

Closed (fixed)

» Closed (works as designed)

updating the simplenews_mail_spool status = 2 is SUPER slow

Comments

Comment #1

Comment #2

Comment #3

Comment #4

Comment #5

Comment #6

Comment #7

Comment #8

Comment #9

Comment #10

Comment #11

Comment #12

Comment #13

Comment #14

News items

Our community

Documentation

Drupal code base

Governance of community