[IPython-User] slow startup time possibly because of sqlite

Steven Willis swillis@compete....
Mon Jan 28 13:06:43 CST 2013


Hi,

I have an install of Python-2.7.3 which I compiled from scratch. I used pip to install ipython 0.13.1. But ipython is very slow to start. I strace'd it like this:

$ strace -o ipython-strace -ff -ttt ipython

The main process was 26131, and I found the largest time between system calls was 5 seconds here:

$ cat ipython-strace.26131 | head -n 8062 | tail -n 16
1359397379.425709 open("/users/swillis/.ipython/profile_default/history.sqlite", O_RDWR|O_CREAT|O_LARGEFILE, 0644) = 3
1359397379.426301 fcntl64(3, F_GETFD)   = 0
1359397379.426347 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
1359397379.426388 fstat64(3, {st_mode=S_IFREG|0644, st_size=7168, ...}) = 0
1359397379.426449 dup(3)                = 4
1359397379.426538 mmap2(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6e97000
1359397379.426591 mprotect(0xf6e97000, 4096, PROT_NONE) = 0
1359397379.426675 clone(child_stack=0xf76964c4, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xf7696bd8, {entry_number:12, base_addr:0xf7696b90, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xf7696bd8) = 26188
1359397379.441139 mmap2(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6697000
1359397379.441254 mprotect(0xf6697000, 4096, PROT_NONE) = 0
1359397379.441351 clone(child_stack=0xf6e964c4, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xf6e96bd8, {entry_number:12, base_addr:0xf6e96b90, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xf6e96bd8) = 26189
1359397379.442286 futex(0xf7696bd8, FUTEX_WAIT, 26188, NULL) = 0
1359397379.448926 futex(0xf6e96bd8, FUTEX_WAIT, 26189, NULL) = 0
1359397384.454540 close(4)              = 0
1359397384.455211 _llseek(3, 0, [0], SEEK_SET) = 0
1359397384.455249 read(3, "SQLite format 3\0\4\0\1\1\0@  \0\0\0\27\0\0\0\0\0"..., 100) = 100

The straces from threads 26188 and 26189:

$ cat ipython-strace.26188
1359397379.441159 set_robust_list(0xf7696be0, 0xc) = 0
1359397379.441276 fcntl64(4, F_SETLK64, {type=F_RDLCK, whence=SEEK_SET, start=0, len=1}, 0xffdc93b0) = 0
1359397379.448152 _exit(0)              = ?

$ cat ipython-strace.26189
1359397379.442303 set_robust_list(0xf6e96be0, 0xc) = 0
1359397379.442379 fcntl64(4, F_SETLK64, {type=F_WRLCK, whence=SEEK_SET, start=0, len=1}, 0xffdc93d0) = 0
1359397384.439285 _exit(0)              = ?

It looks like the main process opens up the history.sqlite file as file descriptor 3, it then dups it as fd 4, then thread 26188 runs fcntl64 on fd 4 which runs very fast, then thread 26189 does the same, but it takes 5 seconds to complete its fcntl64. Any idea what's going on here? My home directory is on NFS, I don't know if that makes a big difference, the other file operations don't seem to be affected by that.

-Steven Willis


More information about the IPython-User mailing list