Slow ipython --pylab and ipython notebook startup

Question

I have switched from ipython 0.10 to 1.1.0. Now I am experiencing very annoying slow-downs of the startup process.

While ipython alone is still up in no time, ipython --pylab takes a very slow start, i.e. ~8 secs (on an Intel(R) Core(TM)2 Duo CPU P9500 @ 2.53GHz system) and even more so the new ipython notebook which I did not have in ipython 0.10, namely ~12 secs.

When I do strace -o tessi.txt -tt ipython --pylab I can identify at least sections which seem to be responsible for large chunks of these delays. Any help on getting rid of those would very welcome.

For the --pylab option, strace's output contains a section which eats away ~5 secs, and which is not present when starting just ipython, namely

10:23:24.331968 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=868, ...}) = 0
10:23:24.332028 socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 9
10:23:24.332074 connect(9, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = 0
10:23:24.332152 sendto(9, "\2\0\0\0\4\0\0\0\35\0\0\0MYHOST.DOM.AIN."..., 41, MSG_NOSIGNAL, NULL, 0) = 41
!! -> 10:23:24.332227 poll([{fd=9, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=9, revents=POLLIN|POLLHUP}])
!! -> 10:23:29.336301 read(9, "\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32) = 32
10:23:29.336533 close(9)                = 0
10:23:29.336839 close(7)                = 0

where I've replace my actual host name with MYHOST.DOM.AIN

In case of ipython notebook there seem to be essentially two such regions. The first one seems to be the same as for ipython --pylab. The second one takes away another ~4 secs

10:39:31.823298 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=868, ...}) = 0
10:39:31.823358 socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 9
10:39:31.823405 connect(9, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = 0
10:39:31.823499 sendto(9, "\2\0\0\0\4\0\0\0\35\0\0\0MYHOST.DOM.AIN."..., 41, MSG_NOSIGNAL, NULL, 0) = 41
!! -> 10:39:31.824166 poll([{fd=9, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=9, revents=POLLIN|POLLHUP}])
!! -> 10:39:36.827298 read(9, "\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32) = 32
10:39:36.827503 close(9)                = 0
10:39:36.827828 close(7)                = 0    

10:39:38.591774 setsockopt(6, SOL_TCP, TCP_NODELAY, [0], 4) = 0
10:39:38.591922 poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 4, 0) = 0 (Timeout)
10:39:38.592007 poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 4, 0) = 0 (Timeout)
!! -> 10:39:38.592049 poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 4, 3600000) = ? ERESTART_RESTARTBLOCK (To be restarted)
!! -> 10:39:42.355658 --- SIGINT (Interrupt) @ 0 (0) ---
10:39:42.355773 write(5, "\0", 1)       = 1
10:39:42.355916 rt_sigreturn(0x2)       = -1 EINTR (Interrupted system call)
10:39:42.356113 rt_sigaction(SIGINT, {0x7f26dc0fbfc6, [], SA_RESTORER, 0x7f26dbe5a2d0}, {0x7f26dc0fbfc6, [], SA_RESTORER, 0x7f26dbe5a2d0}, 8) = 0
10:39:42.356672 clone(child_stack=0x7f26cfb49ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f26cfb4a9d0, tls=0x7f26cfb4a700, child_tidptr=0x7f26cfb4a9d0) = 11084

Any help on how to get rid of these delays would be most welcome.

Finally, and while I'm at it. When I look at strace's remaing output I see, that on startup, ipython tries to open a lot of 'python related' files in places where I would have naively thought that it should never do so, and where my systems python definitely has not been installed? All these many open calls fail. E.g.:

11:11:26.465594 open("/opt/intel/composerxe-2011.3.174/compiler/lib/intel64/tls/libpython2.7.so.1.0", O_RDONLY) = -1 ENOENT (No such file or directory)
11:11:26.465646 stat("/opt/intel/composerxe-2011.3.174/compiler/lib/intel64/tls", 0x7fff0efb0100) = -1 ENOENT (No such file or directory)

or

11:11:26.468293 stat("/usr/local/lib/vtk-5.4/tls/x86_64", 0x7fff0efb0100) = -1 ENOENT (No such file or directory)
11:11:26.468347 open("/usr/local/lib/vtk-5.4/tls/libpython2.7.so.1.0", O_RDONLY) = -1 ENOENT (No such file or directory)

The time total for these calls make up for another significant portion of the remaining slow startup, but I cannot point to a specific time slot. Any idea how to reduce those calls?

Answer 1

See https://github.com/ipython/ipython/issues/4298 for the rest of this issue

Answer 2

1) I suggest not starting with --pylab we encourage people to use %matplotlib once started. the overhead of starting when using --pylabis most probably due to importing packages we don't have access to. There is for example bugs on ArchLinux where each ipython --pylab takes hundreds of MB because of memory leak somewhere not in IPython code.

The access to sockets still seem weird, getting to know exactly where this come from could help.

2) The second one with notebook is probably due to ZMQ and the start of some communication over sockets on localhost. We know that in some occasion it can take some times, but we need also to find out which part of the code is slow to do smth about that. NOtebook also start a webserver so network operation are expected.

3) Is probably due to some library we use, we don't open such tings explicitly in ipython. especially VTK. Do you have a profile that load specific things ?

You could try to open an issue on IPython tracker, but we will probably ask you to dig deeper to know what are the python call in ipython that take so much time. The question of startup time have already been asked between core dev.

The consensus was that this would be "best effort" but we are definitively a too small teem to have this as priority. Still a integration with tool like vbech to track regression would be nice and if someone is motivated to digg into slow call, we'll be glad to do our best to improve things.