django, celery and mysql: Lost connection to MySQL server during query

[Massimiliano della Rovere]

Using django 1.2.3 with celery 2.0.3 and django-celery 2.0.3 and mysql
5.1.41 on kubuntu 10.04, I receive the following error:
OperationalError(2013, 'Lost connection to MySQL server during query').

The error occurs every time the task is executed and seems to be
related to the execution time, in fact when I process smaller files
(let's say 8000 lines) everything is fine and task ends with success.
The current files count about 242000 lines and execution started at
13:17:01 and failed at 16:08:47.
I noticed using htop that cpu load is about 100% on both cores;
(Intel(R) Xeon(R) CPU 3040 @ 1.86GHz). Could this cause the mysql
error 2013?

The python code is quite long, and I am not copying it here because
the error is mysql related...
Does anybody have any ideas?

[2010-10-09 15:50:15,265: ERROR/MainProcess] Task
igs.tasks.advanced_statistics[e886e849-cfcc-42b9-a171-0a2d56778f6b]
raised exception: OperationalError(2013, 'Lost connection to MySQL
server during query')
Traceback (most recent call last):
File "/usr/local/lib/python2.6/dist-packages/celery-2.0.3-py2.6.egg/celery/worker/job.py",
line 86, in execute_safe
return self.execute(*args, **kwargs)
File "/usr/local/lib/python2.6/dist-packages/celery-2.0.3-py2.6.egg/celery/worker/job.py",
line 101, in execute
return super(WorkerTaskTrace, self).execute()
File "/usr/local/lib/python2.6/dist-packages/celery-2.0.3-py2.6.egg/celery/execute/trace.py",
line 62, in execute
retval = self._trace()
File "/usr/local/lib/python2.6/dist-packages/celery-2.0.3-py2.6.egg/celery/execute/trace.py",
line 76, in _trace
return handler(trace.retval, trace.exc_type, trace.tb, trace.strtb)
File "/usr/local/lib/python2.6/dist-packages/celery-2.0.3-py2.6.egg/celery/worker/job.py",
line 122, in handle_failure
exc = self.task.backend.mark_as_failure(self.task_id, exc, strtb)
File "/usr/local/lib/python2.6/dist-packages/celery-2.0.3-py2.6.egg/celery/backends/base.py",
line 46, in mark_as_failure
traceback=traceback)
File "/usr/local/lib/python2.6/dist-packages/celery-2.0.3-py2.6.egg/celery/backends/base.py",
line 152, in store_result
return self._store_result(task_id, result, status, traceback)
File "/usr/local/lib/python2.6/dist-packages/django_celery-2.0.3-py2.6.egg/djcelery/backends/database.py",
line 12, in _store_result
traceback=traceback)
File "/usr/local/lib/python2.6/dist-packages/django_celery-2.0.3-py2.6.egg/djcelery/managers.py",
line 42, in _inner
transaction.rollback_unless_managed()
File "/usr/local/lib/python2.6/dist-packages/Django-1.2.3-py2.6.egg/django/db/transaction.py",
line 188, in rollback_unless_managed
connection._rollback()
File "/usr/local/lib/python2.6/dist-packages/Django-1.2.3-py2.6.egg/django/db/backends/mysql/base.py",
line 306, in _rollback
BaseDatabaseWrapper._rollback(self)
File "/usr/local/lib/python2.6/dist-packages/Django-1.2.3-py2.6.egg/django/db/backends/__init__.py",
line 36, in _rollback
return self.connection.rollback()
OperationalError: (2013, 'Lost connection to MySQL server during query')

skype: masdero, icq: 473891447, yim: mas_dero, msn: mas_...@hotmail.com
------------
Mi scriva in italiano; Write me in English; Skribu al mi Esperante!

[Erik Cederstrand]

Den 10/10/2010 kl. 16.34 skrev Massimiliano della Rovere:

> Using django 1.2.3 with celery 2.0.3 and django-celery 2.0.3 and mysql
> 5.1.41 on kubuntu 10.04, I receive the following error:
> OperationalError(2013, 'Lost connection to MySQL server during query').
>
> The error occurs every time the task is executed and seems to be
> related to the execution time, in fact when I process smaller files
> (let's say 8000 lines) everything is fine and task ends with success.
> The current files count about 242000 lines and execution started at
> 13:17:01 and failed at 16:08:47.
> I noticed using htop that cpu load is about 100% on both cores;
> (Intel(R) Xeon(R) CPU 3040 @ 1.86GHz). Could this cause the mysql
> error 2013?
>
> The python code is quite long, and I am not copying it here because
> the error is mysql related..

* Are you keeping a connection open to MySQL the whole time?
* What are the values of your timeout settings in the MySQL server configuration?
* Anything in the MySQL server error log?
* Anything in the MySQL slow query log, if you have that set up?
* Which process(es) on the server is using 100% CPU time?

I suspect that you're opening a connection to the server, doing something in Django for a long time, and then trying to use the connection. At this point MySQL has lost patience and closed the connection.

Thanks,
Erik

[Massimiliano della Rovere]

On Sun, Oct 10, 2010 at 17:12, Erik Cederstrand <er...@cederstrand.dk> wrote:
>
> * Are you keeping a connection open to MySQL the whole time?

I do not know what is the default behaviour of django, but I did not specify any custom option.

> * What are the values of your timeout settings in the MySQL server configuration?

Here is the my.cnf without comments for brevity's sake:
[client]
port            = 3306
socket          = /var/run/mysqld/mysqld.sock

[mysqld_safe]
socket          = /var/run/mysqld/mysqld.sock
nice            = 0

[mysqld]
user            = mysql
socket          = /var/run/mysqld/mysqld.sock
port            = 3306
basedir         = /usr
datadir         = /var/lib/mysql
tmpdir          = /tmp
skip-external-locking

key_buffer              = 16M
max_allowed_packet      = 16M
thread_stack            = 192K
thread_cache_size       = 8
myisam-recover         = BACKUP
query_cache_limit       = 1M
query_cache_size        = 16M
general_log_file        = /var/log/mysql/mysql.log
general_log             = 1
log_error                = /var/log/mysql/error.log
log_slow_queries        = /var/log/mysql/mysql-slow.log
long_query_time = 2
log-queries-not-using-indexes
expire_logs_days        = 10
max_binlog_size         = 100M
binlog_do_db            = include_database_name
binlog_ignore_db        = include_database_name

[mysqldump]
quick
quote-names
max_allowed_packet      = 16M

[isamchk]
key_buffer              = 16M
!includedir /etc/mysql/conf.d/

> * Anything in the MySQL server error log?

nothing unusual in the error log, just the log coming from the two /etc/init.d/mysql.d restart I issued today.

> * Anything in the MySQL slow query log, if you have that set up?

Yes I set it up.
Lots of query issued by my program are in the query log, with no errors reported.
the last one is at 16:08:34 and the error was returned at 16:08:47.

> * Which process(es) on the server is using 100% CPU time?

directly from htop:
PID USER     PRI  NI  VIRT   RES   SHR S CPU% MEM%   TIME+  Command
544 mader     20   0  969M  953M  1444 R 96.0 47.4 50:09.85 python ./manage.py celeryd -l warning

> I suspect that you're opening a connection to the server,
> doing something in Django for a long time, and then
> trying to use the connection. At this point MySQL has
> lost patience and closed the connection.

The db is queried by my code often: the maximum time between two successive queries is no more than 10 seconds, the source of this info is mysql-slow.log.
Again, I do not know how django handles connections...

The python function / task raising this error is part of a billing program.

The task elaborates a csv file with the calls made by the customers: each call "searches" the db for info about the calling number owner and the cost of the called number and other things.
Through empirical tests, I noticed that the error raises after about 165000 lines(=calls) are elaborated (the file usually contains about 245000), but everything is fine with fewer.
One solution could be splitting the file in pieces and then unifying the results but it's not understanding and solving the problem, but just circumventing it...

[Erik Cederstrand]

Den 10/10/2010 kl. 17.55 skrev Massimiliano della Rovere:
> > * Which process(es) on the server is using 100% CPU time?
> directly from htop:
> PID USER PRI NI VIRT RES SHR S CPU% MEM% TIME+ Command
> 544 mader 20 0 969M 953M 1444 R 96.0 47.4 50:09.85 python ./manage.py celeryd -l warning

This, and the fact that you have no errors or seriously long queries in your slow query log, indicates that the MySQL server is operating fine.

Something seems to be timing out on the MySQL side. I'm not sure if you mentioned it, but are these InnoDB tables? The stack trace you posted is in the rollback of a transaction. It's possible that everything is running within the same transaction which MySQL is shutting down at some point. Try this:

SQL> show variables where variable_name LIKE '%timeout%';

to see the values in your current server instance.

If nothing suspicious turns up, I guess it's time to follow the stack trace into the celery source code or where your own code calls celery and add some debugging. Maybe it's a specific query that trips the code. Maybe it's a specific number of queries. Maybe it's at a specific timespan after connecting to MySQL.

Thanks,
Erik

[Massimiliano della Rovere]

I raised the log level to debug:
./manage.py celeryd -l debug

That's the new piece of information:
Out of memory (Needed 24492 bytes)
Out of memory (Needed 24492 bytes)
Out of memory (Needed 24492 bytes)
Out of memory (Needed 24492 bytes)
Out of memory (Needed 24492 bytes)
Out of memory (Needed 24492 bytes)
Out of memory (Needed 16328 bytes)
Out of memory (Needed 16328 bytes)
Out of memory (Needed 16328 bytes)
Out of memory (Needed 16328 bytes)
Out of memory (Needed 16328 bytes)
Out of memory (Needed 16328 bytes)
Out of memory (Needed 8164 bytes)
Out of memory (Needed 8164 bytes)
Out of memory (Needed 8164 bytes)
Out of memory (Needed 8164 bytes)
Out of memory (Needed 8164 bytes)

Looks suspiciously like a memory leak...