Thanks for the advice, Massimo.
Yes, I am calling db.scheduler_task.insert() inside a controller.
On the theory that it could do harm, I put a db.commit() immediately
after the insert and that helped, some.
Now I'm getting the scheduler exception in my worker process about a
third as often, and when it occurs, I can clear the deadlock easier.
Sometimes, I can just restart the worker process. Sometimes I have to
user the MySQL client to stop the query (ie., mysql> kill query
24843;) (I don't want it to sound like I really understand how to
clear the deadlock. I'm just doing something I read about on
stackoverflow.)
I'd like to understand better how the deadlocks arise and what I can
do to prevent them.
Thanks.
David
On Feb 27, 11:11 pm, Massimo Di Pierro <massimo.dipie...@gmail.com>
wrote:
> Do you do this in a controller?
>
> db.scheduler_task.insert(...)
>
> if not. Make sure you db.commit() immediately after. Would is solve
> the problem?
>
> On Feb 27, 9:14 pm, David Phillips <david.phillips....@gmail.com>
> wrote:
>
>
>
>
>
>
>
> > I am experiencing database deadlocks in a worker processes that is
> > being scheduled by web2py's newscheduler.
>
> > I'm using the latest web2py with Python 2.7.2 and MySQL (a recent
> > release) on OS X 10.7.3.
>
> > The worker does a lengthy calculation that I wanted to take off the
> > http thread. Every time I get a certain action, I schedule the thread
> > programmatically like this:
>
> > db.scheduler_task.insert(application_name = 'geo', task_name =
> > 'match_task',
> > function_name = 'match_listings', vars =
> > json.dumps(vars))
>
> > In my testing I execute this task about once every two seconds. It has
> > failed in two separate tests after about an hour.
>
> > I'm getting this traceback:
>
> > File "/Users/davidp/dev/python/web2py/gluon/shell.py", line 214, in
> > run
> > exec(python_code, _env)
> > File "<string>", line 1, in <module>
> > File "/Users/davidp/dev/python/web2py/gluon/scheduler.py", line 363,
> > in loop
> > MetaScheduler.loop(self)
> > File "/Users/davidp/dev/python/web2py/gluon/scheduler.py", line 255,
> > in loop
> > task = self.pop_task()
> > File "/Users/davidp/dev/python/web2py/gluon/scheduler.py", line 392,
> > in pop_task
> > grabbed.update(assigned_worker_name='',status=QUEUED)
> > File "/Users/davidp/dev/python/web2py/gluon/dal.py", line 6346, in
> > update
> > return self.db._adapter.update(tablename,self.query,fields)
> > File "/Users/davidp/dev/python/web2py/gluon/dal.py", line 1093, in
> > update
> > self.execute(sql)
> > File "/Users/davidp/dev/python/web2py/gluon/dal.py", line 1359, in
> > execute
> > return self.log_execute(*a, **b)
> > File "/Users/davidp/dev/python/web2py/gluon/dal.py", line 1353, in
> > log_execute
> > ret = self.cursor.execute(*a, **b)
> > File "/Users/davidp/dev/python/web2py/gluon/contrib/pymysql/
> > cursors.py", line 108, in execute
> > self.errorhandler(self, exc, value)
> > File "/Users/davidp/dev/python/web2py/gluon/contrib/pymysql/
> > connections.py", line 184, in defaulterrorhandler
> > raise errorclass, errorvalue
> > InternalError: (1213, u'Deadlockfound when trying to get lock; try
> > restarting transaction')
>
> > When executed, the task does this SQL select:
>
> > expr = '''SELECT *, ( 3959 * acos (cos (radians (%s)) * cos (radians
> > (lat)) *
> > cos (radians (lon) - radians (%s)) + sin (radians (%s)) * sin
> > (radians (lat))))
> > AS distance FROM users HAVING distance < radius;''' % (point[0],
> > point[1], point[0])
> > nearby_users = db.executesql(expr, as_dict = True)
>
> > and then does a read to collect some statistics to track performance:
>
> > num_listings = db (db.listings.id > 0).count()
>
> > During this time, I am receiving asynchronous http requests that
> > insert, update and delete from this table (and another table, too).
>
> > My MySQL client responds to a "show engine innodb status;" command
> > this way:
>
> > ------------------------
> > LATEST DETECTEDDEADLOCK
> > ------------------------
> > 120227 20:38:16
> > *** (1) TRANSACTION:
> > TRANSACTION 27AFF, ACTIVE 0 sec starting index read
> > mysql tables in use 1, locked 1
> > LOCK WAIT 3 lock struct(s), heap size 376, 2 row lock(s), undo log
> > entries 1
> > MySQL thread id 19816, OS thread handle 0x10c5db000, query id 1558959
> > localhost 127.0.0.1 root Updating
> > UPDATE scheduler_task SET status='QUEUED',assigned_worker_name=''
> > WHERE ((scheduler_task.assigned_worker_name = 'Mycroft.local#d600fcf2-
> > a363-4870-bd24-1ad3694f6a62') AND (scheduler_task.status =
> > 'ASSIGNED'))
> > *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
> > RECORD LOCKS space id 0 page no 3031 n bits 120 index `PRIMARY` of
> > table `geo`.`scheduler_task` trx id 27AFF lock_mode X waiting
> > Record lock, heap no 2 PHYSICAL RECORD: n_fields 20; compact format;
> > info bits 0
> > 0: len 4; hex 8000002c; asc ,;;
> > 1: len 6; hex 000000024db1; asc M ;;
> > 2: len 7; hex 6a00000d4c2f35; asc j L/5;;
> > 3: len 3; hex 67656f; asc geo;;
> > 4: len 10; hex 656d61696c207461736b; asc email task;;
> > 5: len 4; hex 6d61696e; asc main;;
> > 6: len 6; hex 515545554544; asc QUEUED;;
> > 7: len 10; hex 73656e645f656d61696c; asc send_email;;
> > 8: len 2; hex 5b5d; asc [];;
> > 9: len 2; hex 7b7d; asc {};;
> > 10: len 1; hex 54; asc T;;
> > 11: len 8; hex 8000124c9afce86c; asc L l;;
> > 12: len 8; hex 8000124c9afee908; asc L ;;
> > 13: len 8; hex 8000124c9b0c193a; asc L :;;
> > 14: len 4; hex 80000000; asc ;;
> > 15: len 4; hex 80000e10; asc ;;
> > 16: len 4; hex 80000dde; asc ;;
> > 17: len 4; hex 8000000d; asc ;;
> > 18: len 8; hex 8000124c9afec1f8; asc L ;;
> > 19: len 0; hex ; asc ;;
>
> > *** (2) TRANSACTION:
> > TRANSACTION 27AFD, ACTIVE 0 sec fetching rows
> > mysql tables in use 2, locked 2
> > 52 lock struct(s), heap size 6960, 2775 row lock(s), undo log entries
> > 9
> > MySQL thread id 19817, OS thread handle 0x10c598000, query id 1558955
> > localhost 127.0.0.1 root Sending data
> > UPDATE scheduler_task SET status='QUEUED',assigned_worker_name=''
> > WHERE ((scheduler_task.assigned_worker_name IN (SELECT
> > scheduler_worker.worker_name FROM scheduler_worker WHERE
> > (scheduler_worker.last_heartbeat < '2012-02-27 20:38:07'))) AND
> > (scheduler_task.status IN ('RUNNING','ASSIGNED','QUEUED')))
> > *** (2) HOLDS THE LOCK(S):
> > RECORD LOCKS space id 0 page no 3031 n bits 120 index `PRIMARY` of
> > table `geo`.`scheduler_task` trx id 27AFD lock_mode X
> > Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format;
> > info bits 0
> > 0: len 8; hex 73757072656d756d; asc supremum;;
>
> > There are pages of other stuff besides, but this seems most to the
> > point. I suppose if I knew more about databases that would mean
> > something to me.
>
> > I also have two other tasks that I schedule manually, one running
> > every hour and another every minute, although the firstdeadlock
> > occurred before the once-a-minute task was installed and neither time
> > did it occur near the time of execution of the hourly task.
>
> > I understand that deadlocks occur when different processes acquire
> > locks in different orders. But I don't see how I can control that if
> > I'm using the DAL.
>
> > Any insight would be appreciated.
