slow handling of keyboard input

[efiring]

I am now at

commit 376addf1c5ba97e228ee16549306c64ddc18d4a9
Merge: 1214ad1 971ca49
Author: Fernando Perez 
Date:   Fri Dec 16 11:27:00 2011 -0800

With this, and with earlier commits, I have been running into situations where, with "ipython --pylab", keyboard input handling is unusably slow; each keypress triggers a burst of disk activity. It is not related to the number of commands entered in a given session; right now I have a session where it was almost impossible to edit the 5th command in the session. The previous command involved heavy computation (using mpl to generate a couple thousand png files), but no screen output and only moderate memory usage.

[fperez]

@efiring, do you think this could be the same problem as #481? What backend are you using? Can you replicate the issue with other backends? As you can see from the discussion on #481, we're a bit stumped, but obviously we need to do something about it. Any extra info you may have could help shed some light on the problem...

[efiring]

Fernando, the symptom is similar in that both involve sluggish response to keystrokes, but I am running linux (ubuntu 11.04), with gtkagg backend. Also, 481 does not mention what I am seeing: disk activity with every keypress. The problem occurs in a session with no plotting to the screen at all, and it does not appear immediately, but really seems to result from running a long plot-to-file series. Once it starts in a given session, it's hopeless--the only thing to do is kill the session and start a new one. I can test tomorrow with a different backend, and with bare ipython console, no --pylab. The operation that seems to reliably trigger this takes a long time to run, so I can't test quickly.

[fperez]

OK, that's good to know. We'll keep it a separate issue then. It's a bummer that it takes so long to cause it; as that's going to make it pretty tricky to track this down. If you can create a synthetic test that causes it at least we could try to run the same code here... Definitely knowing whether it happens with any other backend would help at least narrow down whether we have a memory leak in the event loop integration code (which is backend-specific). Also, it could give you a temporary workaround if another backend doesn't show the problem.

The reason I'm thinking memory leak is b/c all that disk activity sounds like it could be swapping. Did you notice the typical symptoms of swapping (other applications getting sluggish, etc)? I just can't imagine what else could be creating all that disk activity...

[efiring]

Fernando,

No, it's not a memory leak--memory consumption is moderate and
stable--and it was not swapping, or at least not owing to lack of
memory. Each keypress appears to be causing some sort of on-disk
lookup. I know this sounds very strange; even if some file were being
consulted, or the directory structure, one would expect it to be largely
in cache, and therefor not to access the physical disk. The behavior
was clear when I ran into it yesterday; we will see what happens today.

[efiring]

I did a run similar to the one yesterday, except that I used plain "ipython", no --pylab, and the slowdown did not appear. So, it does seem to be related to the gtk input hook. I was going to try --pylab=tk, but it renders the machine unusable by repeatedly flashing up a plot window in whatever workspace I am trying to use. The same with --pylab=wx. I'm now trying --pylab=qt.

[efiring]

Well, with --pylab=qt I found yet another pathology: memory consumption increased continuously, putting the system in swap hell. It definitely did not do that with gtk. With qt, when I used Ctrl-C to kill the python function, it eventually returned the ipython prompt, but the increasing memory consumption and swapping kept on going until the system recognized another Ctrl-C and again gave me the same prompt. At this point the ipython process was still holding on to all that memory, but it was not grabbing more, and the response to keyboard input was normal.

The events involving getting control back included this (starting from the end of the traceback):

/usr/local/lib/python2.7/dist-packages/matplotlib/_pylab_helpers.pyc in destroy(num)
     68         #print len(Gcf.figs.keys()), len(Gcf._activeQue)

     69         manager.destroy()
---> 70         gc.collect()
     71 
     72     @staticmethod

KeyboardInterrupt: 

In [4]: 
KeyboardInterrupt - Ctrl-C again for new prompt

KeyboardInterrupt

In [4]: 

So the first Ctrl-C was recognized in a gc call, while closing a figure.

I then tried importing gc and running gc.collect from the prompt; this put the system right back in swap hell, with memory first going down very slowly, but then turning around and growing; at that point I had to kill the process.

Next I encapsulated the operation in a script, with matplotlib.use("qt4agg"), and ran that from the command line. No problem, no memory leak.

Then I ran the same script from within "ipython --pylab=qt" using the run magic; still no problem!

Then I ran the script within a new "ipython --pylab=qt" using execfile, and the memory leak appeared as expected, just as when running the commands by typing them in.

So, what is the difference between typing the commands in (or using execfile) and running them as a script via the run magic? And how does that difference lead to a devastating memory leak in the former case?

Later today I will try to come up with a minimal script to reproduce the problem(s).

[fperez]

Oh boy, this looks ugly. It would certainly be great to have a way for us to reproduce the problem. I'm pinging @minrk and @takluyver in case theycan pitch in b/c as of tomorrow morning I'll be offline until the New Year. Sorry to see you going through this ugly mess, but we've obviously never seen anything like it or we wouldn't have released :)

[efiring]

Here is a script that reproduces the memory leak when using execfile but not using run magic, both inside a "ipython --pylab=qt" session:

import matplotlib
matplotlib.use("qt4agg")

from matplotlib.cbook import report_memory

import matplotlib.pyplot as plt
import numpy as np

def dummyplot():
    fig = plt.figure()
    ax = fig.add_subplot(1,1,1)
    ax.imshow(np.random.rand(50,60), interpolation='nearest')
    fig.savefig("test.png")
    plt.close(fig)

def tester(n=1000):
    for i in range(n):
        dummyplot()
        if i % 10 == 0:
            print i, report_memory(i)

tester()

If you comment out the second line and "execfile" it in a "ipython --pylab=gtk" session, there is a very much smaller rate of memory consumption. Using run magic, there is no leakage.
So, we have a way to reproduce the qt big memory leak problem, and the gtk small memory leak problem; unfortunately, this does not yet reproduce the slow keyboard response problem, even when run with 5000 plots.

[takluyver]

I thought this was about problems when you weren't showing the window? The script you posted just pops up matplotlib windows in whatever workspace I try to use. By the time I managed to kill it, it claims to have opened 220 windows, which was using 167 MB memory (I assume the numbers are in KB).

[efiring]

Whether or not it pops up windows depends on the backend at least, and maybe on the OS. Who knows, maybe also on window manager settings. On my ubuntu 11.04 system, with gtkagg and qt4agg backends, it does not pop up windows; with tkagg and wxagg it does. Hence the targets for identifying the problem are the former two--but do they pop up windows on your system? I recognize that all this may be pointing to something that needs to be changed in mpl, or possibly jointly in mpl and ipython. On the other hand, the fact that the problem appears only when the plotting is run via execfile or from the keyboard, and not via "run", suggests to me that maybe it can be solved in ipython; or at least that understanding what the difference is may point to what needs to be changed in mpl.

[takluyver]

I ran it with execfile in ipython --pylab=qt, as you suggested, but the
windows were popping up. It didn't seem to be using excessive memory,
though, given how many windows were open.

This is with Ubuntu 11.10 and matplotlib 1.0.1.

[efiring]

OK, I tried it again, --pylab=qt, and I still don't see any windows, but I do see the bottom panel (horizontal bar showing windows in the present workspace) twitching, so apparently the windows are being opened and closed before they can actually end up on my screen. This still should not cause any memory consumption at all; each window is being closed before the next one is opened. Nothing in the test script is keeping a reference to anything that would be generated with each plot.
With --pylab=gtk, there is not even any twitching of the bottom panel, and the memory leak is relatively slow.

Whether any of this is related to the problem that originally started this issue is not clear to me, since I still don't have a simple test case illustrating that original problem of slow command response.

[takluyver]

Maybe it's related to the window manager, but in my case they didn't appear
to be closing. At one point, I tried Alt-tab, and there were dozens of tiny
tiles for that process group.

[efiring]

What window manager are you using? I'm using metacity, Gnome 2 with no effects.

[efiring]

I wonder whether perhaps closing a figure needs to explicitly do something to trigger handling of window manager events; maybe they are just piling up in the window manager event queue, with some combinations of gui toolkit and window manager.

[takluyver]

I'm using Unity, so I think Compiz is the WM, but I've not checked.

[jenshnielsen]

I Just tested it on ubuntu11.10. Using unity2D the windows don't open but the do using unity3D (with compiz).
All tested using pylab=qt

[efiring]

Thank you. Now that I think about it, it makes sense that they should open, in that this involves plotting in interactive mode, which triggers an immediate draw upon calling plt.figure(). Whether the gui and window manager get around to rendering the window before it is closed is a function of the way they handle a rapid sequence of events, which varies. So, the real problem is not the rapid-fire opening and closing of windows, for the systems on which this occurs, but rather the continuing memory consumption, which should not occur. (The solution for the obnoxious windows when all one wants to do is write a png file is to turn off interactive mode.) The memory leak is not affected by explicit gc.collect(); it is already being called by plt.close(fig). Instead, either the underlying gui toolkit is leaking, or ipython (or mpl) is holding a growing set of references. Or both.

[jenshnielsen]

From my brief tests I don't think that it is really leaking. If you reduce the number to n=100 figures and run it twice
it only appears to leak memory the first time. In the second run the same memory is used again. So it seems more like the
garbage collection is not allowed to run until after the script has finished.

[fperez]

I'm sorry to do this, but I'm downgrading this to 'high' priority from 'blocker', simply because we can't realistically block the entire release on an issue we have no clue how to fix.

It's a real bummer, and I hope we'll be able to track what's going on at some point, but absent any progress, we can't stall a release on this. And in fact, we were violating the 'blocker' marker already since we'd bumped this from 0.11 to 0.12 to 0.13, so if anything I'm just being upfront about what we've already done.

[efiring]

This issue morphed into a description of other problems, but I think the original problem (heavy disk activity on keyboard input) is a duplicate of #2608. I haven't been hurt by it recently, probably because I have been working on things that simply haven't triggered it to a noticeable degree. See also matplotlib/matplotlib#1530.