Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Slow speed due to many calls #11

Open
wdoekes opened this issue Feb 16, 2017 · 0 comments
Open

Slow speed due to many calls #11

wdoekes opened this issue Feb 16, 2017 · 0 comments

Comments

@wdoekes
Copy link
Member

wdoekes commented Feb 16, 2017

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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@wdoekes