"MySQL server has gone away" errors happening more and more with db-based sessions?

[Yarin]

We've had our production application running problem free for 10 months, but in the past month or so we've started encountering "MySQL server has gone away" errors sporadically, but with increasing frequency. Currently it is happening every few days, sometimes several times a day. This has never happened to the app in test or development environments. 

These factors lead me to believe this problem is manifesting itself as a result of increased activity. Still, our loads are relatively low. We may have a handful of users connected at any one time, but not more than 10.

Looking at our Newrelic database reports, we're seeing that the a huge spike in db clock time always coincides with the errors, and the culprit is always the web2py_session_ UPDATE call. (It may possibly correlated with new user signups, but we haven't been able to confirm this)

Stranger still, in one of these incidents there were over a hundred calls made to web2py_session_{app} UPDATE, many times the number of total requests made to the app over the same period.

Traces:

Traceback (most recent call last):
  File "/opt/web-apps/web2py/gluon/main.py", line 624, in wsgibase
    BaseAdapter.close_all_instances('rollback')
  File "/opt/web-apps/web2py/gluon/dal.py", line 529, in close_all_instances
    db._adapter.close(action)
  File "/opt/web-apps/web2py/gluon/dal.py", line 509, in close
    getattr(self, action)()
  File "/opt/web-apps/web2py/gluon/dal.py", line 1655, in rollback
    if self.connection: return self.connection.rollback()
  File "/usr/lib/python2.6/site-packages/newrelic-1.12.0.9/newrelic/hooks/database_dbapi2.py", line 76, in rollback
    return self._nr_connection.rollback()
OperationalError: (2006, 'MySQL server has gone away')

and

Traceback (most recent call last):
  File "/opt/web-apps/web2py/gluon/main.py", line 551, in wsgibase
    session._try_store_in_db(request, response)
  File "/opt/web-apps/web2py/gluon/globals.py", line 726, in _try_store_in_db
    table._db(table.id == record_id).update(**dd)
  File "/opt/web-apps/web2py/gluon/dal.py", line 8812, in update
    ret = db._adapter.update(tablename,self.query,fields)
  File "/opt/web-apps/web2py/gluon/dal.py", line 1372, in update
    self.execute(sql)
  File "/opt/web-apps/web2py/gluon/dal.py", line 1694, in execute
    return self.log_execute(*a, **b)
  File "/opt/web-apps/web2py/gluon/dal.py", line 1688, in log_execute
    ret = self.cursor.execute(*a, **b)
  File "/usr/lib/python2.6/site-packages/newrelic-1.12.0.9/newrelic/hooks/database_dbapi2.py", line 36, in execute
    return self._nr_cursor.execute(sql, *args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/MySQLdb/cursors.py", line 173, in execute
    self.errorhandler(self, exc, value)
  File "/usr/lib64/python2.6/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
OperationalError: (1205, 'Lock wait timeout exceeded; try restarting transaction')

What could be the cause of all this? Any ideas welcome.

[Niphlod]

if you're storing sessions in the database an update is made for every request that changes the session ..... can you confirm that this would be the case (i.e. your app does a lot of session.whatever changes) ?

[Niphlod]

even so, 50 seconds spent on a single-row update (that has a PK involved cause the update is somewhat

update session_table
set locked = False,
client_ip=blablabla,
modified_datetime=now,
session_data=blablablabla,
unique_key=blablabla
where id = number

)
is a ginormous amount of time . Any network hiccups between the app server and the mysql instance ?

[Yarin]

Hi Niphlod

• We do basic session updates on some but not all requests- but as you point out, that doesn't explain the huge update times or their sporadic nature, especially with our light load of under 100 requests an hour.
• The db and app server are on the same private rackspace cloud network, and we've never seen connection issues between the two. And if that were the case, we'd expect similar hangups on other db calls, not just web2py_session_{app} UPDATE 

[Niphlod]

either than a large blob/object in the session I really can't see how an update so simple (syntax-wise) takes 50 seconds (when the minimum reported time is 0.8ms) on mysql end.
edit: did you try to inspect how much data is in the "longest session_data" column ?

[Yarin]

Largest session_data fields were 12 KiB

[Yarin]

OK, now I've run into some special weirdness- I don't know if it's related, but it makes no sense to me:

When I run a count of session records grouped by client IP, I get some very big numbers at the top end:

SELECT client_ip, COUNT( * ) AS count
FROM `web2py_session_sidekick` 
GROUP BY client_ip
ORDER BY count DESC 
LIMIT 0 , 30

Some client ips have 100+ session records associated with them!? For example, my own IP has 186 session records- including 13 where the modified_datetime field equals TODAY... This makes no sense.  I did not log into my app from 13 different devices today. Why would a single user connecting from a single device have so many session records??

[Niphlod]

everyone with a different unique_key ?

[Yarin]

Yes- I've documented this issue in a new question - please see: https://groups.google.com/d/msg/web2py/A7P4HoST-Lg/NZ3kmTTwVG0J