jsonserver high RAM usage

[robmcmullen]

Expected Behaviour

jsonserver using a relatively static amount of RAM

Actual Behaviour

jsonserver process increases size, seemingly without bounds until it swaps everything out of memory except itself.

Steps to Reproduce

As noted in #318, and by @qocu it's not clear exactly what is causing it, but it seems to be related to large projects or multiple Sublime windows open in a project

ST3, Anaconda and OS versions

ST3126, Anaconda 2.1.18, linux 4.1.12 kernel

ST3 Console Logs

Nothing useful I expect, but here: st3.txt

Anaconda's JsonServer Logs

I've not had it fail again since this jsonserver log; will update when it happens again. anaconda-traceback.txt

[robmcmullen]

Forgot to mention I'm using a 2.7.10 interpreter in a virtualenv

[qocu]

Python: 3.4.3 in virtualenv ( multiple virtualenvs in multiple sublime windows )
OS: Linux kernel 4.9.6, Gentoo
Projects have a lot of different files aside from python files, html, css, js etc ( django projects )
Only way to reproduce I've encountered is when this happens one. When I kill jsonserver without restarting sublime problems occurs again after a while.

[robmcmullen]

I'm on Gentoo also; probably not a factor, but still interesting.

I'm using two really big libraries in the virtualenv, wxPython (related to davidhalter/jedi#805 probably) and the Enthought Traits/Pyface libraries. There's also a fair amount of Cython code, but I think Jedi skips over that?

[DamnWidget]

I will try to reproduce it, things go rogue when two windows are open using the same project is probably logical on Linux as there is only one Unix Domain Socket and two windows trying to start anaconda server over that socket, with only one window is weird.

What I can see in the logs is that Jedi breaks.

[DamnWidget]

Ok I did several crazy things to try to reproduce the logs that @robmcmullen pasted but I was not able to make Jedi go rogue I just exhausted my computer RAM and had to restart.

To do so, I had to open 7 windows in a project that was using wxPython, each instance of Jedi that needs to complete wxPython uses 6Gb of memory (I have 32GB on this computer)

Jedi seems to use that huge amount of memory always that imports the xwPython module as use iPython demonstrates
22233 damnwid+ 20 0 6457.0m 6.005g 0.0 19.1 0:25.90 S ipython2

We have a problem here because the last version of Jedi that is on master, fixed this problem, this is the comparative between the current jedi version bundled into anaconda and the latest one:

Anaconda's bundled version:
17880 damnwidge 20 0 6399M 6156M 8300 S 0.0 19.2 0:00.00 /usr/bin/python2 /usr/bin/ipython2

Latest Jedi version:
15365 damnwidge 20 0 574M 186M 25200 S 0.0 0.6 0:00.00 /usr/bin/python2 /usr/bin/ipython2

As you can see, is much better but we have a problem with the latest Jedi version but that version caused some performance issues in OSX and I had to rollback it #632

So what we have here is a big problem to me because I do not have the time to hunt down the problem in OSX and update Jedi, apart from that latest version of Jedi API is not compatible with anaconda and I had to modify anaconda to make it work with it so it is not an in-drop replacement and probably that could be causing some issue.

I will update this as soon as I have anything to update.

P.S: as a suggestion, try to do not open more than one window into the project and if you do use another Python interpreter for the second one, one interpreter that does not see the library that is using too many memory

[robmcmullen]

Thanks for taking a look at it. Sounds like we can't just plop in the new dev version of Jedi because of the API changes. I'd be willing to try to backport the fix from the current Jedi to the version that is compatible with Anaconda, but I can't find the commit in Jedi that fixes it. Any ideas which commit might have been the resolution? Or was it a series of changes that would be difficult to backport?

[DamnWidget]

I think is easier if you just use the jedi_bump anaconda branch

[robmcmullen]

At the jedi_bump branch, it's made a huge difference so far. jsonserver seems to be holding in the 300-400MB range.

[DamnWidget]

@qocu did you try the jedi_bump branch? It improved your experience?

[robmcmullen]

The same python process has been running for these past 4 days and it has only grown slightly to 500MB. I'd say that it fixes my issue.

[qocu]

@DamnWidget haven't tried it yet, I'll be working on large projects again ( on small I haven't noticed problems even on master branch ) in couple of days so I will post observations.

[robmcmullen]

Aaaaand, I jinxed myself. The jsonserver process is currently spinning and growing, but pretty slowly compared to last time. In 4 minutes, it's only at 1.2GB. I couldn't get jsonserver to run in debug mode using jedi_bump, for some reason it would never talk to sublime. I'll try again.

[robmcmullen]

Got jsonserver running in debug mode. I'll post a followup if it starts spinning again in a few days.

[robmcmullen]

Could it be related to different projects using the same virtualenv? I have two related projects that I was using the same virtualenv to edit and test, both projects were open and both were getting linted automatically.

In debug mode, you specify a single project and it doesn't appear to do any linting or anything of other projects that are also open using the same virtualenv. I'll try a second debug jsonserver for the other project and see what happens.

[DamnWidget]

On linux you have to use the same name as your project for the -p argument when you start the server in debug mode as ST3 will connect to a Unix Domain Socket, I also recommend to delete the socket file if it already exists before to start the server, the .sock file will be located at ~/.local/share/anaconda/run/<project>/anaconda.sock

[robmcmullen]

I worked for several hours with the two projects open (separate jsonserver process for each) and one of them produced this when it started spinning and growing memory:

INFO:root:client requests: doc
Received method: doc, handler: jedi
<class 'handlers.jedi_handler.JediHandler'> handler retrieved from registry
^CTraceback (most recent call last):
  File "anaconda_server/jsonserver.py", line 376, in <module>
    server.serve_forever()
  File "anaconda_server/jsonserver.py", line 165, in serve_forever
    asyncore.loop()
  File "/usr/lib/python2.7/asyncore.py", line 216, in loop
    poll_fun(timeout, map)
  File "/usr/lib/python2.7/asyncore.py", line 156, in poll
    read(obj)
  File "/usr/lib/python2.7/asyncore.py", line 83, in read
    obj.handle_read_event()
  File "/usr/lib/python2.7/asyncore.py", line 449, in handle_read_event
    self.handle_read()
  File "/usr/lib/python2.7/asynchat.py", line 165, in handle_read
    self.found_terminator()
  File "anaconda_server/jsonserver.py", line 105, in found_terminator
    self.handle_command(handler_type, method, uid, vid, data)
  File "anaconda_server/jsonserver.py", line 132, in handle_command
    handler(method, data, uid, vid, self.return_back, DEBUG_MODE).run()
  File "/data/home/rob/.config/sublime-text-3/Packages/anaconda/anaconda_server/handlers/jedi_handler.py", line 30, in run
    super(JediHandler, self).run()
  File "/data/home/rob/.config/sublime-text-3/Packages/anaconda/anaconda_server/lib/anaconda_handler.py", line 48, in run
    command(**kwargs)
  File "/data/home/rob/.config/sublime-text-3/Packages/anaconda/anaconda_server/handlers/jedi_handler.py", line 99, in doc
    Doc(self.callback, self.uid, self.script, html)
  File "/data/home/rob/.config/sublime-text-3/Packages/anaconda/anaconda_server/commands/doc.py", line 33, in __init__
    super(Doc, self).__init__(callback, uid)
  File "/data/home/rob/.config/sublime-text-3/Packages/anaconda/anaconda_server/commands/base.py", line 14, in __init__
    self.run()
  File "/data/home/rob/.config/sublime-text-3/Packages/anaconda/anaconda_server/commands/doc.py", line 41, in run
    definitions = self.script.goto_definitions()
  File "anaconda_lib/jedi/api/__init__.py", line 190, in goto_definitions
    module_node = self._get_module_node()
  File "anaconda_lib/jedi/cache.py", line 89, in wrapper
    result = method(self, *args, **kwargs)
  File "anaconda_lib/jedi/api/__init__.py", line 137, in _get_module_node
    parser = FastParser(self._grammar, self._source, self.path)
  File "anaconda_lib/jedi/parser/diff.py", line 33, in __call__
    parser.module = parser._parsed = d.update(new_lines)
  File "anaconda_lib/jedi/parser/diff.py", line 176, in update
    self._copy_from_old_parser(line_offset, i2, j2)
  File "anaconda_lib/jedi/parser/diff.py", line 230, in _copy_from_old_parser
    self._parse(until_line_new)
  File "anaconda_lib/jedi/parser/diff.py", line 285, in _parse
    node = self._try_parse_part(until_line)
  File "anaconda_lib/jedi/parser/diff.py", line 333, in _try_parse_part
    return self._active_parser.parse(tokenizer=tokenizer)
  File "anaconda_lib/jedi/parser/__init__.py", line 267, in parse
    root_node = super(ParserWithRecovery, self).parse(self._tokenize(tokenizer))
  File "anaconda_lib/jedi/parser/__init__.py", line 136, in parse
    self._parsed = self.pgen_parser.parse(tokenizer)
  File "anaconda_lib/jedi/parser/pgen2/parse.py", line 123, in parse
    if self.addtoken(type_, value, start_pos, prefix):
  File "anaconda_lib/jedi/parser/pgen2/parse.py", line 149, in addtoken
    self.shift(type_, value, newstate, prefix, start_pos)
  File "anaconda_lib/jedi/parser/pgen2/parse.py", line 184, in shift
    newnode = self.convert_leaf(self.grammar, type_, value, prefix, start_pos)
  File "anaconda_lib/jedi/parser/__init__.py", line 184, in convert_leaf
    if type == tokenize.NAME:
KeyboardInterrupt

Clearly it's an issue in Jedi but because it can take hours to trigger. Is there any way to flag the underlying jedi to print out debug info also?

[DamnWidget]

The strange thing about these logs of yours is that there is no error, just traceback so we do not even know what the problem is. To enable Jedi to print to the stdout just add set_debug_function() to anaconda_lib/jedi/api/__init__.py after sys.setrecursionlimit(2000) and before the class class NotFOundError

[robmcmullen]

I know, Jedi is just spinning somehow but it's not clear where. I've added the set_debug_function, and also I discovered the sys.settrace hook, so I've added function call tracing for jedi and maybe that will also help pinpoint something. The logs grow by megabytes for each jedi call, so I'll let you know anything interesting if it happens before my filesystem gets full. :)

[robmcmullen]

I hit it just now. Sifting through 650M of log data, there's the command Received method: autocomplete, handler: jedi that triggers about 185M of trace logs. Attached is a summary using grep -b -E "speed\:|Received method\:|dbg\:" anaconda.omnivore.1.log, showing the byte number in that 650M log file.

It seems like jedi is piclking some data and that's really slow in this instance when parsing wxPython. Previous instances don't have this huge time.

doclog1.txt

I think it's time I open a ticket with Jedi.

[robmcmullen]

What's the likelihood that this is being caused by "from BLAH import *"? There are quite a few of those floating around in the code that I haven't yet refactored out.

[DamnWidget]

I think the best option here is open a bug in the Jedi repository, my exposure to Jedi internal is not so good but I think star imports should not produce any problem.

[qocu]

Haven't run into this issue for a long time now, can't reproduce.
Maybe it was triggered by a specific software configuration ?
Still I'm using the almost the same configuration with one difference of ditching GitGutter.

[AndreasBackx]

Closing Sublime Text does not close the process, I have to kill the process specifically. I don't have anything in my console atm because I restarted ST. I'll try to update this issue with more information once I come across it again and have some more information to share.

I am getting the following ignored exception pretty often with Python 3.5.3 (which has been resolved in later versions):

Exception ignored in: <function WeakValueDictionary.__init__.<locals>.remove at 0x7fa0bcb77048>
Traceback (most recent call last):
  File "/home/andreas/.pyenv/versions/project/lib/python3.5/weakref.py", line 117, in remove
TypeError: 'NoneType' object is not callable

I only use star imports for my signal's receivers in Django because those all need to be imported when the Django app is loaded. This is on Python 3.5.3 with the following installs:

Package                  Version
------------------------ -------
alabaster                0.7.8  
amqp                     2.2.1  
Babel                    2.3.4  
beautifulsoup4           4.4.1  
billiard                 3.5.0.3
celery                   4.1.0  
click                    6.7    
coverage                 4.4.1  
decorator                4.1.2  
defusedxml               0.5.0  
Django                   1.11.3 
django-appconf           1.0.2  
django-compressor        2.1.1  
django-dirtyfields       1.2.1  
django-jinja             2.3.1  
django-livereload-server 0.2.3  
django-sass-processor    0.5.4  
docker                   2.4.2  
docker-pycreds           0.2.1  
docutils                 0.12   
first                    2.0.1  
gitdb2                   2.0.2  
github3.py               1.0.0a4
GitPython                2.1.5  
imagesize                0.7.1  
ipython                  6.1.0  
ipython-genutils         0.2.0  
jedi                     0.10.2 
Jinja2                   2.9.6  
kombu                    4.1.0  
libsass                  0.11.1 
MarkupSafe               0.23   
oauthlib                 1.1.2  
pexpect                  4.2.1  
pickleshare              0.7.4  
pip                      9.0.1  
pip-tools                1.9.0  
pluggy                   0.3.1  
prompt-toolkit           1.0.15 
psycopg2                 2.7.3  
ptyprocess               0.5.2  
py                       1.4.31 
Pygments                 2.1.3  
PyJWT                    1.4.0  
python3-openid           3.0.10 
pytz                     2016.4 
rcssmin                  1.0.6  
requests                 2.10.0 
requests-oauthlib        0.6.1  
rjsmin                   1.0.12 
setuptools               36.2.4 
simplegeneric            0.8.1  
six                      1.10.0 
smmap2                   2.0.3  
snowballstemmer          1.2.1  
social-auth-app-django   1.2.0  
social-auth-core         1.4.0  
Sphinx                   1.6.3  
sphinxcontrib-websupport 1.0.1  
tornado                  4.5.1  
tox                      2.7.0  
traitlets                4.3.2  
uritemplate.py           0.3.0  
uwsgidecorators          1.1.0  
vine                     1.1.4  
virtualenv               15.0.2 
wcwidth                  0.1.7  
websocket-client         0.37.0 
wheel                    0.29.0 

[DamnWidget]

Anaconda version @AndreasBackx?

[AndreasBackx]

@DamnWidget my apologies, the version I've got is 2.1.20. This is on Arch Linux 4.12.3-1.

[DamnWidget]

Can you reproduce it as you wish? If so, can I have the code that triggers the issue and an explanation about how to reproduce it?

[AndreasBackx]

I just started working on it again after having the process killed and I'm currently not seeing any elevated process or RAM usage on the server. I'll check more often from now on to get an indication of what might be the issue.

[AndreasBackx]

Okay, Anaconda just made my PC come to a crawl and made me force shutdown it because I couldn't even start to open a terminal in order to shut it down. I noticed the elevated CPU usage in my bar on my desktop and when I started top, it immediately came to a crawling halt and I heard my music playing bit by bit (literally). Chromium was also acting weird because it seemed to be out of memory. For now I still can't provide you with any real code to reproduce the issue, but this project will be open sourced in the future if that is any help at all. :/

I probably caught it at a good time earlier today, but now it probably slurped all of my RAM and swap space and made my PC crash I guess. So it took 32GB of memory on average (16GB RAM and 16GB swap).

Edit: It seemed to have messed top up:

[DamnWidget]

Hi @AndreasBackx
When Jedi goes rogue you can notice it immediately because anaconda stops working, no linting, no completions or any other anaconda feature. It will be useful if you also have a terminal tailing the JsonServer logs as you will see that it stalls trying to do goto_definition when doc is being called. If you are able to provide with a method to reproduce I will be able to fix it (I could reproduce with python 2.7 in the previous version of anaconda but I can't reproduce it anymore since v2.1.20).

[AndreasBackx]

Alright, I'm starting to tail the file right now and let's hope I notice it before it goes berserk again.

[qocu]

So far so good.
Recently I had few django projects that triggered jsonserver frenzy almost always, I had to disable Anaconda completely.
After seeing that update was related to this issue I've turned Anaconda on again and so far it's ok. Since then problem didn't occur even once. Hope I won't jinx it but thanks.