client-reader worker can leak FDs and then swallow requests #1981

Activity

1. ara4n

   changed the title [-]client-reader worker can leak FDs and then swallowing requests[/-] [+]client-reader worker can leak FDs and then swallow requests[/+] on Mar 10, 2017
2. ara4n commented on Mar 10, 2017

   

   ara4n

   on Mar 10, 2017

   MemberAuthor

   More actions

   Looks like it was getting stuck on acquiring the linearizer lock for sets of state events, starting at ~8pm last night and then swallowing reqs and leaking FDs until it started to fail all requests, and then I restarted it at 23:45. This is pretty damning:

   
   
3. ara4n commented on Mar 10, 2017

   

   ara4n

   on Mar 10, 2017

   MemberAuthor

   More actions

   may be related to #1858
4. ara4n

   added

   z-bug(Deprecated Label)(Deprecated Label)

   p1

   on Mar 10, 2017
5. erikjohnston commented on Mar 10, 2017

   

   erikjohnston

   on Mar 10, 2017

   Last edited by erikjohnston

   Member

   More actions

   From the logs:

   2017-03-09 20:53:52,658 - twisted - 131 - CRITICAL -  - Unhandled error in Deferred:
   2017-03-09 20:53:52,658 - twisted - 131 - CRITICAL -  - 
   Traceback (most recent call last):
     File "/home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 653, in _runCallbacks
       current.result = callback(current.result, *args, **kw)
     File "/home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1357, in gotResult
       _inlineCallbacks(r, g, deferred)
     File "/home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1347, in _inlineCallbacks
       deferred.errback()
     File "/home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 500, in errback
       self._startRunCallbacks(fail)
     File "/home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 567, in _startRunCallbacks
       self._runCallbacks()
     File "/home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 666, in _runCallbacks
       current.result = failure.Failure(captureVars=self.debug)
     File "/home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/python/failure.py", line 206, in __init__
       if isinstance(exc_value, str) and exc_type is None:
   RuntimeError: maximum recursion depth exceeded while calling a Python object
   

   and its full of:

   2017-03-09 20:53:48,953 - synapse.util.async - 201 - INFO - POST-14459 - Acquired linearizer lock 'state_resolve_lock' for key frozenset([29319867L, 29319869L])
   2017-03-09 20:53:48,953 - synapse.util.async - 208 - INFO - POST-14459 - Releasing linearizer lock 'state_resolve_lock' for key frozenset([29319867L, 29319869L])
   2017-03-09 20:53:48,988 - synapse.util.async - 201 - INFO - POST-14459 - Acquired linearizer lock 'state_resolve_lock' for key frozenset([29325139L, 29325140L])
   2017-03-09 20:53:48,988 - synapse.util.async - 208 - INFO - POST-14459 - Releasing linearizer lock 'state_resolve_lock' for key frozenset([29325139L, 29325140L])
   

   from about 23:47 20:47, though they all seem to mostly hit the cache.
6. ara4n commented on Mar 10, 2017

   

   ara4n

   on Mar 10, 2017

   MemberAuthor

   More actions

   @erikjohnston did you mean 20:47?
7. erikjohnston commented on Mar 10, 2017

   

   erikjohnston

   on Mar 10, 2017

   Member

   More actions

   Why, yes, I did, thanks
8. erikjohnston commented on Mar 10, 2017

   

   erikjohnston

   on Mar 10, 2017

   Member

   More actions

   After catching it doing a bunch of CPU work and hitting it with pyflame, it seems to be 73% of its time in get_order_for_room
9. erikjohnston commented on Mar 10, 2017

   

   erikjohnston

   on Mar 10, 2017

   Member

   More actions

   35% of that is resolving state groups
10. erikjohnston commented on Mar 10, 2017

    

    erikjohnston

    on Mar 10, 2017

    Last edited by erikjohnston

    Member

    More actions

    https://matrix.org/_matrix/media/v1/download/jki.re/LhSjIcCyIwwmSQWcvNEAchZT/flame.svg is a snapshot over a period of 10s.
11. erikjohnston commented on Mar 20, 2017

    

    erikjohnston

    on Mar 20, 2017

    Member

    More actions

    I have changed it so that get_order_for_room is much cheaper, so that should help a lot. #1989
12. ara4n commented on Mar 20, 2017

    

    ara4n

    on Mar 20, 2017

    MemberAuthor

    More actions

    do we know why it got permenantly stuck?
13. richvdh commented on Apr 20, 2017

    

    richvdh

    on Apr 20, 2017

    Member

    More actions

    sounds like this got fixed.
14. richvdh

    closed this as completedon Apr 20, 2017
15. richvdh commented on Oct 11, 2017

    

    richvdh

    on Oct 11, 2017

    Member

    More actions

    (sounds like it didn't get fixed (properly), but will be by #2532)