pstore
pstore copied to clipboard
ossobv
Slow speed due to many calls
Look at the following.
There are problems with:
- multiple calls to the backend (for session cookie + for the actual data)
- python imports that we do not need
- python imports that take long
- python imports that fail to recompile because they're owned by root, and stale (look for unlink() in strace)
- communication through dbus? (dns? gpg?)
$ time strace -tt `which pstore` --store-url=http://pstore2.osso.lan --store-url=http://pstore.osso.lan ns1 2>&1 >/dev/null | wtimediff | grep -vF +0.000 -B1
0.0 09:51:24.873981 execve("/usr/local/bin/pstore", ["/usr/local/bin/pstore", "--store-url=http://pstore2.osso."..., "--store-url=http://pstore.osso.l"..., "ns1"], [/* 78 vars */]) = 0
--
+0.000065 09:51:24.913310 close(3) = 0
+0.001386 09:51:24.914696 stat("/usr/local/bin", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
--
+0.000024 09:51:24.917314 read(4, "\3\363\r\n\"2\335Wc\0\0\0\0\0\0\0\0\6\0\0\0@\0\0\0s9\1\0\0d\0"..., 4096) = 4096
+0.001299 09:51:24.918613 fstat(4, {st_mode=S_IFREG|0644, st_size=4730, ...}) = 0
--
+0.000026 09:51:24.922638 open("/usr/lib/python2.7/hashlib.x86_64-linux-gnu.so", O_RDONLY) = -1 ENOENT (No such file or directory)
+0.001165 09:51:24.923803 open("/usr/lib/python2.7/hashlib.so", O_RDONLY) = -1 ENOENT (No such file or directory)
--
+0.000035 09:51:24.925849 munmap(0x7fe971b18000, 173743) = 0
+0.001193 09:51:24.927042 close(6) = 0
--
+0.000031 09:51:24.929016 stat("/usr/local/lib/python2.7/dist-packages/pstorelib/__init__.py", {st_mode=S_IFREG|0644, st_size=1226, ...}) = 0
+0.001175 09:51:24.930191 stat("/usr/local/lib/python2.7/dist-packages/pstorelib/__init__", 0x7ffe0e5c41d0) = -1 ENOENT (No such file or directory)
--
+0.00003 09:51:24.933745 open("/usr/local/bin/struct.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
+0.001313 09:51:24.935058 stat("/usr/lib/python2.7/struct", 0x7ffe0e5c3840) = -1 ENOENT (No such file or directory)
--
+0.000033 09:51:24.940007 open("/usr/lib/python2.7/json/_json.so", O_RDONLY) = -1 ENOENT (No such file or directory)
+0.001338 09:51:24.941345 open("/usr/lib/python2.7/json/_jsonmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
--
+0.000465 09:51:24.943076 close(7) = 0
+0.006374 09:51:24.949450 close(6) = 0
--
+0.000077 09:51:24.952456 read(7, "ion into a key= functiont\1\0\0\0Kc\0"..., 4096) = 1941
+0.001156 09:51:24.953612 read(7, "", 4096) = 0
--
+0.00003 09:51:24.954196 open("/usr/lib/python2.7/plat-x86_64-linux-gnu/_ssl.x86_64-linux-gnu.so", O_RDONLY) = -1 ENOENT (No such file or directory)
+0.008279 09:51:24.962475 open("/usr/lib/python2.7/plat-x86_64-linux-gnu/_ssl.so", O_RDONLY) = -1 ENOENT (No such file or directory)
--
+0.000033 09:51:24.964245 munmap(0x7fe971b18000, 173743) = 0
+0.002917 09:51:24.967162 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fe9706f9000
--
+0.000049 09:51:24.971890 stat("/usr/local/bin/keyword", 0x7ffe0e5c2ee0) = -1 ENOENT (No such file or directory)
+0.001295 09:51:24.973185 open("/usr/local/bin/keyword.x86_64-linux-gnu.so", O_RDONLY) = -1 ENOENT (No such file or directory)
--
+0.000094 09:51:24.974629 close(7) = 0
+0.001915 09:51:24.976544 close(6) = 0
--
+0.00009 09:51:24.978038 close(8) = 0
+0.001071 09:51:24.979109 close(7) = 0
--
+0.000031 09:51:24.982480 open("/usr/lib/python2.7/urllib2.so", O_RDONLY) = -1 ENOENT (No such file or directory)
+0.007549 09:51:24.990029 open("/usr/lib/python2.7/urllib2module.so", O_RDONLY) = -1 ENOENT (No such file or directory)
--
+0.00014 09:51:24.995543 brk(0x559819773000) = 0x559819773000
+0.001008 09:51:24.996551 socket(AF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
--
+0.000034 09:51:24.999542 mprotect(0x7fe96efd7000, 4096, PROT_READ) = 0
+0.002502 09:51:25.002044 mprotect(0x7fe96f1fb000, 4096, PROT_READ) = 0
+0.004529 09:51:25.006573 mprotect(0x7fe96f23f000, 12288, PROT_READ) = 0
--
+0.000031 09:51:25.009053 ppoll([{fd=3, events=POLLIN}], 1, {44, 999802000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {44, 994581134})
+0.005519 09:51:25.014572 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\0018\0\0\0z\177\2\0>\0\0\0\5\1u\0\2\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
+0.000046 09:51:25.014618 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"\6\1s\0\10\0\0\0:1.41621\0\0\0\0\0\0\0\0\10\1g\0\ta(i"..., 112}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 112
+0.001288 09:51:25.015906 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
+0.000032 09:51:25.015938 close(3) = 0
+0.001021 09:51:25.016959 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
--
+0.000115 09:51:25.017857 recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 8192, 0, NULL, NULL) = 825
+0.060395 09:51:25.078252 stat("/usr/local/lib/python2.7/dist-packages/pstorelib/gpg", 0x7ffe0e5c3120) = -1 ENOENT (No such file or directory)
--
+0.000026 09:51:25.081069 mmap(NULL, 2171872, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 8, 0) = 0x7fe96e4fa000
+0.001115 09:51:25.082184 mprotect(0x7fe96e50c000, 2093056, PROT_NONE) = 0
--
+0.000025 09:51:25.088842 read(4, "sysconfdir:/etc/gnupg\nbindir:/us"..., 1023) = 330
+0.00129 09:51:25.090132 read(4, "", 1023) = 0
--
+0.000024 09:51:25.091187 read(4, "gpg:GPG for OpenPGP:/usr/bin/gpg"..., 1023) = 248
+0.001137 09:51:25.092324 read(4, "", 1023) = 0
--
+0.000025 09:51:25.092563 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fe971b149d0) = 25519
+0.011721 09:51:25.104284 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=25519, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
--
+0.000022 09:51:25.107538 read(4, "gpgconf (GnuPG) 2.1.15\nCopyright"..., 79) = 79
+0.001315 09:51:25.108853 close(4) = 0
--
+0.000022 09:51:25.109223 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fe971b149d0) = 25525
+0.008834 09:51:25.118057 wait4(25525, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 25525
+0.002888 09:51:25.120945 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=25525, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
--
+0.000025 09:51:25.121131 select(13, [4 9], [12], NULL, {1, 0}) = 2 (in [4], out [12], left {0, 999998})
+0.001466 09:51:25.122597 select(5, [4], [], NULL, {0, 0}) = 1 (in [4], left {0, 0})
--
+0.000029 09:51:25.122659 select(13, [], [12], NULL, {0, 0}) = 1 (out [12], left {0, 0})
+0.001066 09:51:25.123725 close(3) = 0
--
+0.000034 09:51:25.124896 select(10, [4 9], [], NULL, {1, 0}) = 1 (in [4], left {0, 886731})
+0.11334 09:51:25.238236 select(5, [4], [], NULL, {0, 0}) = 1 (in [4], left {0, 0})
--
+0.000034 09:51:25.241071 sendmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 128}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
+0.001005 09:51:25.242076 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\r\0\0\0\1\0\0\0E\0\0\0\6\1s\0\10\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
--
+0.000029 09:51:25.243351 ppoll([{fd=3, events=POLLIN}], 1, {44, 998976000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {44, 995407972})
+0.003788 09:51:25.247139 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\0018\0\0\0~\177\2\0>\0\0\0\5\1u\0\2\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
--
+0.000091 09:51:25.248862 recvfrom(3, "HTTP/1.1 404 NOT FOUND\r\nServer: "..., 8192, 0, NULL, NULL) = 262
+0.018812 09:51:25.267674 close(3) = 0
--
+0.000051 09:51:25.269095 sendmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 128}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
+0.001041 09:51:25.270136 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\r\0\0\0\1\0\0\0E\0\0\0\6\1s\0\10\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
+0.002174 09:51:25.272310 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{":1.41623\0\0\0\0\0\0\0\0\5\1u\0\1\0\0\0\10\1g\0\1s\0\0"..., 77}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 77
--
+0.000041 09:51:25.273864 ppoll([{fd=3, events=POLLIN}], 1, {44, 998727000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {44, 994717165})
+0.004274 09:51:25.278138 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\0018\0\0\0\202\177\2\0>\0\0\0\5\1u\0\2\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
--
+0.000085 09:51:25.279803 recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 8192, 0, NULL, NULL) = 825
+0.065226 09:51:25.345029 pipe([4, 6]) = 0
--
+0.000027 09:51:25.346946 select(11, [4 10], [], NULL, {1, 0}) = 1 (in [4], left {0, 997677})
+0.002371 09:51:25.349317 select(5, [4], [], NULL, {0, 0}) = 1 (in [4], left {0, 0})
--
+0.000033 09:51:25.350408 select(11, [4 10], [], NULL, {1, 0}) = 1 (in [4], left {0, 892916})
+0.107123 09:51:25.457531 select(5, [4], [], NULL, {0, 0}) = 1 (in [4], left {0, 0})
--
+0.000035 09:51:25.459506 sendmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 128}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
+0.001034 09:51:25.460540 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\r\0\0\0\1\0\0\0E\0\0\0\6\1s\0\10\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
--
+0.000029 09:51:25.461829 ppoll([{fd=3, events=POLLIN}], 1, {44, 998965000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {44, 995565996})
+0.003618 09:51:25.465447 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\0018\0\0\0\206\177\2\0>\0\0\0\5\1u\0\2\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
--
+0.000647 09:51:25.466176 close(3) = 0
+0.002712 09:51:25.468888 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
--
+0.000095 09:51:25.469779 recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 8192, 0, NULL, NULL) = 547
+0.024157 09:51:25.493936 close(3) = 0
--
+0.000172 09:51:25.494351 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7fe971715630}, {0x559818c731a0, [], SA_RESTORER, 0x7fe971715630}, 8) = 0
+0.004578 09:51:25.498929 write(1, " Machine User"..., 267) = 267
real 0m0.638s
user 0m0.096s
sys 0m0.068s
