search

FAI-CIVL / FAI-Airscore

AirScore - online paragliding / hanggliding GAP-based scoring software.
https://airscore.cc/
GNU General Public License v3.0
13 stars 17 forks source link

Deadlock found when trying to get lock. #223

Closed philderbeast closed 3 years ago

philderbeast commented 3 years ago

If I import the HG Worlds 2019, I note that the tasks [bulk import tracks] each take quite some time, upwards of 4 mins for each task.

I didn't want to wait that long repeating the test so I [bulk import tracks] for each task without first waiting for the prior import of tracks to complete. I encountered an error doing this:

Traceback (most recent call last):
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1256, in _execute_context
    self.dialect.do_executemany(
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/dialects/mysql/mysqldb.py", line 148, in do_executemany
    rowcount = cursor.executemany(statement, parameters)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/cursors.py", line 188, in executemany
    return self._do_execute_many(q_prefix, q_values, q_postfix, args,
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/cursors.py", line 227, in _do_execute_many
    rows += self.execute(sql + postfix)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/cursors.py", line 163, in execute
    result = self._query(query)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/cursors.py", line 321, in _query
    conn.query(q)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/connections.py", line 505, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/connections.py", line 724, in _read_query_result
    result.read()
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/connections.py", line 1069, in read
    first_packet = self.connection._read_packet()
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/connections.py", line 676, in _read_packet
    packet.raise_for_error()
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/protocol.py", line 223, in raise_for_error
    err.raise_mysql_exception(self._data)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/err.py", line 107, in raise_mysql_exception
    raise errorclass(errno, errval)
pymysql.err.OperationalError: (1213, 'Deadlock found when trying to get lock; try restarting transaction')

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/sid/.local/lib/python3.8/site-packages/flask/app.py", line 2464, in __call__
    return self.wsgi_app(environ, start_response)
  File "/home/sid/.local/lib/python3.8/site-packages/flask/app.py", line 2450, in wsgi_app
    response = self.handle_exception(e)
  File "/home/sid/.local/lib/python3.8/site-packages/flask/app.py", line 1867, in handle_exception
    reraise(exc_type, exc_value, tb)
  File "/home/sid/.local/lib/python3.8/site-packages/flask/_compat.py", line 39, in reraise
    raise value
  File "/home/sid/.local/lib/python3.8/site-packages/flask/app.py", line 2447, in wsgi_app
    response = self.full_dispatch_request()
  File "/home/sid/.local/lib/python3.8/site-packages/flask/app.py", line 1952, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/home/sid/.local/lib/python3.8/site-packages/flask/app.py", line 1821, in handle_user_exception
    reraise(exc_type, exc_value, tb)
  File "/home/sid/.local/lib/python3.8/site-packages/flask/_compat.py", line 39, in reraise
    raise value
  File "/home/sid/.local/lib/python3.8/site-packages/flask/app.py", line 1950, in full_dispatch_request
    rv = self.dispatch_request()
  File "/home/sid/.local/lib/python3.8/site-packages/flask_debugtoolbar/__init__.py", line 125, in dispatch_request
    return view_func(**req.view_args)
  File "/home/sid/.local/lib/python3.8/site-packages/flask_login/utils.py", line 272, in decorated_view
    return func(*args, **kwargs)
  File "/app/airscore/user/views.py", line 983, in _upload_track_zip
    resp = frontendUtils.process_zip_file(zip_file=zip_file,
  File "/app/airscore/core/frontendUtils.py", line 909, in process_zip_file
    data = process_archive(task, zip_file, check_g_record=grecord, track_source=track_source)
  File "/app/airscore/core/frontendUtils.py", line 887, in process_archive
    assign_and_import_tracks(tracks, task, track_source, check_g_record=check_g_record)
  File "/app/airscore/core/trackUtils.py", line 172, in assign_and_import_tracks
    verify_and_import_track(pilot, mytrack, task, print=new_print)
  File "/app/airscore/core/trackUtils.py", line 189, in verify_and_import_track
    save_track(result, task.id)
  File "/app/airscore/core/pilot/flightresult.py", line 684, in save_track
    update_waypoints_achieved(result)
  File "/app/airscore/core/pilot/waypointachieved.py", line 63, in update_waypoints_achieved
    db.bulk_insert_mappings(TblTrackWaypoint, mappings)
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 2880, in bulk_insert_mappings
    self._bulk_save_mappings(
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 2979, in _bulk_save_mappings
    transaction.rollback(_capture_exception=True)
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/util/langhelpers.py", line 68, in __exit__
    compat.raise_(
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
    raise exception
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 2967, in _bulk_save_mappings
    persistence._bulk_insert(
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/orm/persistence.py", line 95, in _bulk_insert
    _emit_insert_statements(
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/orm/persistence.py", line 1083, in _emit_insert_statements
    c = cached_connections[connection].execute(statement, multiparams)
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1011, in execute
    return meth(self, multiparams, params)
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/sql/elements.py", line 298, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1124, in _execute_clauseelement
    ret = self._execute_context(
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1316, in _execute_context
    self._handle_dbapi_exception(
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1510, in _handle_dbapi_exception
    util.raise_(
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
    raise exception
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1256, in _execute_context
    self.dialect.do_executemany(
  File "/home/sid/.local/lib/python3.8/site-packages/sqlalchemy/dialects/mysql/mysqldb.py", line 148, in do_executemany
    rowcount = cursor.executemany(statement, parameters)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/cursors.py", line 188, in executemany
    return self._do_execute_many(q_prefix, q_values, q_postfix, args,
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/cursors.py", line 227, in _do_execute_many
    rows += self.execute(sql + postfix)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/cursors.py", line 163, in execute
    result = self._query(query)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/cursors.py", line 321, in _query
    conn.query(q)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/connections.py", line 505, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/connections.py", line 724, in _read_query_result
    result.read()
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/connections.py", line 1069, in read
    first_packet = self.connection._read_packet()
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/connections.py", line 676, in _read_packet
    packet.raise_for_error()
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/protocol.py", line 223, in raise_for_error
    err.raise_mysql_exception(self._data)
  File "/home/sid/.local/lib/python3.8/site-packages/pymysql/err.py", line 107, in raise_mysql_exception
    raise errorclass(errno, errval)
sqlalchemy.exc.OperationalError: (pymysql.err.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction')
[SQL: INSERT INTO `tblTrackWaypoint` (track_id, wpt_id, name, rawtime, lat, lon, altitude) VALUES (%(track_id)s, %(wpt_id)s, %(name)s, %(rawtime)s, %(lat)s, %(lon)s, %(altitude)s)]
[parameters: ({'track_id': 1391, 'wpt_id': 87, 'name': 'SSS', 'rawtime': 39616, 'lat': 46.25385, 'lon': 13.1487, 'altitude': 544.0}, {'track_id': 1391, 'wpt_id': 88, 'name': 'TP01', 'rawtime': 42748, 'lat': 46.14533333333333, 'lon': 12.990983333333332, 'altitude': 487.0}, {'track_id': 1391, 'wpt_id': 89, 'name': 'TP02', 'rawtime': 46708, 'lat': 46.178016666666664, 'lon': 13.39895, 'altitude': 508.0}, {'track_id': 1391, 'wpt_id': 90, 'name': 'TP03', 'rawtime': 48759, 'lat': 46.27858333333333, 'lon': 13.126666666666667, 'altitude': 566.0}, {'track_id': 1391, 'wpt_id': 91, 'name': 'ESS', 'rawtime': 51418, 'lat': 46.075700000000005, 'lon': 13.359266666666667, 'altitude': 488.0}, {'track_id': 1391, 'wpt_id': 92, 'name': 'Goal', 'rawtime': 51452.0, 'lat': 46.07211666666667, 'lon': 13.3661, 'altitude': 496.0})]
(Background on this error at: http://sqlalche.me/e/13/e3q8)
kuaka commented 3 years ago

Unless this was running on the prod docker-compose there is nothing to do about this. Running concurrent intensive operations is well beyond the scope of the flask dev web server.

In prod there is queuing of background tasks (outside of the web server). If this was or were to be run on prod there may still be an issue if using the local dev mySQL as opposed to a proper dedicated mySQL instance, however it is less likely.

philderbeast commented 3 years ago

This was with docker-compose -f docker-compose-dev-local.yml up. Can we not have queuing for that setup too?

kuaka commented 3 years ago

regarding the time to process 1 task, given there are 120 pilots and the tasks are lengthy I think that is acceptable. There are some speedups that could be done but at this stage it has been fast enough.

This was with docker-compose -f docker-compose-dev-local.yml up. Can we not have queuing for that setup too?

I think redis workers could be set up for the dev server but not the SSE messages. This would be quite an effort to setup and fracture the code. IMHO far more effort than the 5-10 seconds it takes to switch between dev and prod (without the nice messages processing a track). Pull requests welcome, but in terms of time invested I think the payback period would take more years than the life of the project.

kuaka commented 3 years ago

I just had a thought that perhaps you are unaware just how simple it is to swtich. When dev is running Ctl-c will stop it in the terminal. docker-compose -f docker-compose-prod-local.yml up will start prod and then you can continue in the browser where you left off (provided you have logged in previously)

https://user-images.githubusercontent.com/19358239/103106613-b6761800-469b-11eb-8f62-3dd34e609b17.mov