656176 - buildapi starts running slow when a self-serve requests fails ?

Status: RESOLVED WORKSFORME

(Release Engineering :: General, defect, P3)

Description

[Nick Thomas [:nthomas] (UTC+12)]

Today we had this in buildapi's paster.log:

2011-05-10 14:52:58,161 INFO  [sqlalchemy.engine.base.Engine.0x...00ac] [worker 19] BEGIN
2011-05-10 14:52:58,161 INFO  [sqlalchemy.engine.base.Engine.0x...00ac] [worker 19] INSERT INTO jobrequests (action, who, "when", completed_at, what, complete_data) VALUES (?, ?, ?, ?, ?, ?)
2011-05-10 14:52:58,161 INFO  [sqlalchemy.engine.base.Engine.0x...00ac] [worker 19] ('rebuild_build', '[e-mail]', 1305064378.1607111, None, '{"priority": 0, "bid": 3493701}', None)
2011-05-10 14:52:58,162 INFO  [sqlalchemy.engine.base.Engine.0x...00ac] [worker 19] ROLLBACK
2011-05-10 14:52:58,162 ERROR [buildapi.lib.mq] [worker 19] Couldn't create JobRequest row
Traceback (most recent call last):
  File "/home/catlee/buildapi-official/buildapi/lib/mq.py", line 183, in send_msg
    s.commit()
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/orm/session.py", line 653, in commit
    self.transaction.commit()
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/orm/session.py", line 364, in commit
    self._prepare_impl()
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/orm/session.py", line 348, in _prepare_impl
    self.session.flush()
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/orm/session.py", line 1346, in flush
    self._flush(objects)
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/orm/session.py", line 1427, in _flush
    flush_context.execute()
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/orm/unitofwork.py", line 293, in execute
    rec.execute(self)
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/orm/unitofwork.py", line 426, in execute
    uow
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/orm/mapper.py", line 1761, in _save_obj
    execute(statement, params)
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/engine/base.py", line 1157, in execute
    params)
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/engine/base.py", line 1237, in _execute_clauseelement
    return self.__execute_context(context)
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/engine/base.py", line 1268, in __execute_context
    context.parameters[0], context=context)
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/engine/base.py", line 1367, in _cursor_execute
    context)
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/engine/base.py", line 1360, in _cursor_execute
    context)
  File "/home/catlee/.virtualenvs/pylons/lib/python2.5/site-packages/SQLAlchemy-0.6.1-py2.5.egg/sqlalchemy/engine/default.py", line 277, in do_execute
    cursor.execute(statement, parameters)
OperationalError: (OperationalError) database is locked u'INSERT INTO jobrequests (action, who, "when", completed_at, what, complete_data) VALUES (?, ?, ?, ?, ?, ?)' ('rebuild_build', '[e-mail]', 1305064378.1607111, None, '{"priority": 0, "bid": 3493701}', None)

And afterwards started getting proxy errors like this:
[Tue May 10 14:53:45 2011] [error] [client 10.2.74.128] (70007)The timeout specified has expired: proxy: error reading status line from remote server localhost, referer: h
ttps://build.mozilla.org/buildapi/self-serve/try/rev/bb03789cbaec[Tue May 10 14:53:45 2011] [error] [client 10.2.74.128] proxy: Error reading from remote server returned by /buildapi/self-serve/try/build, referer: https://build.mozilla.
org/buildapi/self-serve/try/rev/bb03789cbaec
until 15:12, and some more later in the afternoon.

We also had nagios warnings about builds-running & builds-pending, indicating buildapi was running slowly.

There aren't strong causal links here, and they may all be a function of ESX or a DB running slowly, but I think it's suspicious that there were 54 requests in the period 14:48 to 14:52 and then we got an error and slowness. As we start getting more scripts built on self-serve we will need to handle requests at higher rates.

Comment 1

[Mike Taylor [:bear]]

catlee, 

Is this an myisam table style that is running into issues because now it's multiple acceeses issue?

This smells like a row/table lock timeout from the database that is being lost by the client.

Comment 3

[Chris AtLee [:catlee]]

No, this db is a local sqlite file right now. See also bug 635506.

I did push a fix as noted in https://bugzilla.mozilla.org/show_bug.cgi?id=656501#c2 that seems to have made things better today.