(Migrated) Startup time

forum-admin · June 20, 2016, 4:18pm

(This message has been automatically imported from the retired mailing list)

I wonder if there is anything which can be done to reduce the zato
startup time?

The following tests are in a VirtualBox VM (1GB RAM) running Ubuntu
14.04, on a Macbook Air 2011 (i7/1.8GHz), which may not be the fastest
environment in the world; but even after several runs so everything is
in cache, it still takes nearly 7 seconds just to start up the "zato"
command line tool:

$ time /opt/zato/2.0.3/bin/zato
usage: zato [-h] [–version]
{ca,check-config,component-version,create,decrypt,delete,encrypt,enmasse,info,from-config,migrate,quickstart,service,start,stop,update}
…
zato: error: too few arguments

real 0m6.808s
user 0m3.897s
sys 0m0.919s

A simple cluster restart takes over a minute:

$ time ./zato-qs-restart.sh
Stopping the Zato cluster quickstart-816651
Load-balancer /opt/zato/env/qs-1/load-balancer shutting down
Load-balancer’s agent /opt/zato/env/qs-1/load-balancer shutting down
[1/4] Load-balancer stopped
Server /opt/zato/env/qs-1/server1 shutting down
[2/4] server1 stopped
Server /opt/zato/env/qs-1/server2 shutting down
[3/4] server2 stopped
Web admin /opt/zato/env/qs-1/web-admin shutting down
[4/4] Web admin stopped
Zato cluster quickstart-816651 stopped
Starting the Zato cluster quickstart-816651
Running sanity checks
[1/6] Redis connection OK
[2/6] SQL ODB connection OK
[3/6] Load-balancer started
[4/6] server1 started
[5/6] server2 started
[6/6] Web admin started
Zato cluster quickstart-816651 started
Visit https://zato.io/support for more information and support options

real 1m7.279s
user 0m36.606s
sys 0m6.692s

Even at that point, the cluster is not functional. If I access
http://x.x.x.x:8183/zato/service/details?cluster=1 then for about 15
seconds I get ‘connection refused’. Then after that the connection is
accepted, but times out:

Traceback (most recent call last): File
"/opt/zato/2.0.3/zato-web-admin/src/zato/admin/web/views/init.py",
line 299, in call response = self.invoke_admin_service() File
"/opt/zato/2.0.3/zato-web-admin/src/zato/admin/web/views/init.py",
line 262, in invoke_admin_service return func(self.service_name,
self.input) File
"/opt/zato/2.0.3/zato-web-admin/src/zato/admin/middleware.py", line 68,
in invoke response = super(Client, self).invoke(*args,
headers={‘X-Zato-Forwarded-For’: self.forwarder_for}, **kwargs) File
"/opt/zato/2.0.3/zato-client/src/zato/client/init.py", line 400, in
invoke return self._invoke(async=False, *args, **kwargs) File
"/opt/zato/2.0.3/zato-client/src/zato/client/init.py", line 397, in
_invoke return super(AnyServiceInvoker, self).invoke(dumps(request),
ServiceInvokeResponse, async, headers, output_repeated) File
"/opt/zato/2.0.3/zato-client/src/zato/client/init.py", line 334, in
invoke return self.inner_invoke(request, response_class, async, headers)
File “/opt/zato/2.0.3/zato-client/src/zato/client/init.py”, line
322, in inner_invoke self.max_cid_repr, self.logger, output_repeated)
File “/opt/zato/2.0.3/zato-client/src/zato/client/init.py”, line
243, in init super(ServiceInvokeResponse, self).init(*args,
**kwargs) File
"/opt/zato/2.0.3/zato-client/src/zato/client/init.py", line 82, in
init self.init() File
"/opt/zato/2.0.3/zato-client/src/zato/client/init.py", line 181, in
init raise ValueError(msg) ValueError: inner.status_code 504, JSON
parsing error `

504 Gateway Time-out

The server didn’t respond in time. `

If I leave it for another minute or two and then retry, then finally it
works. So I have to allow 2-3 minutes of downtime for a cluster restart.

Debugging with strace:

“strace /opt/zato/2.0.3/bin/zato” runs for over 2 minutes, spewing to
stderr
it seems to be trying to load the same libraries over and over again.
I can get some stats like this:

$ strace /opt/zato/2.0.3/bin/zato 2>&1 | perl -ne ‘print “$1\n” if
m#/eggs/(.*?)/#’ | uniq -c | wc -l
17309

$ strace /opt/zato/2.0.3/bin/zato 2>&1 | perl -ne ‘print “$1\n” if
m#/eggs/(.*?)/#’ | sort | uniq -c
1631 alembic-0.6.5-py2.7.egg
1452 amqp-1.0.11-py2.7.egg
1410 anyjson-0.3.3-py2.7.egg
1388 argh-0.23.2-py2.7.egg
834 arrow-0.4.2-py2.7.egg
783 Babel-1.3-py2.7.egg
782 base32_crockford-0.2.0-py2.7.egg
776 bcrypt-1.0.2-py2.7.egg
777 behave-1.2.4-py2.7.egg
776 blist-1.3.6-py2.7-linux-x86_64.egg
1198 boto-2.35.1-py2.7.egg
786 bunch-1.0.1-py2.7.egg
764 bzr-2.6.0-py2.7-linux-x86_64.egg
792 candv-1.1.1-py2.7.egg
758 cassandra_driver-2.0.2-py2.7-linux-x86_64.egg
886 cffi-0.8.2-py2.7-linux-x86_64.egg
746 chai-0.4.0-py2.7.egg
746 click-1.1-py2.7.egg
746 cmd2-0.6.7-py2.7.egg
746 codegen-1.0-py2.7.egg
746 colander-1.0b1-py2.7.egg
767 collective.recipe.patch-0.2.2-py2.7.egg
758 ConcurrentLogHandler-0.9.1-py2.7.egg
746 configobj-5.0.5-py2.7.egg
728 cov_core-1.7-py2.7.egg
729 coverage-3.7.1-py2.7-linux-x86_64.egg
756 crontab-0.20-py2.7.egg
965 cryptography-0.5.1-py2.7-linux-x86_64.egg
716 cssselect-0.9.1-py2.7.egg
716 datadiff-1.1.5-py2.7.egg
716 decorator-3.4.0-py2.7.egg
744 dictalchemy-0.1.2.6-py2.7.egg
708 distribute-0.6.34-py2.7.egg
704 Distutils2-1.0a4-py2.7.egg
858 Django-1.3.7-py2.7.egg
698 django_debug_toolbar_django13-0.8.4-py2.7.egg
698 django_openid_auth-0.5-py2.7.egg
698 elasticsearch-0.4.5-py2.7.egg
698 elasticutils-0.9.1-py2.7.egg
698 enum34-1.0-py2.7.egg
698 Faker-0.0.4-py2.7.egg
699 flake8-2.1.0-py2.7.egg
698 fs-0.4.0-py2.7.egg
698 futures-2.1.6-py2.7.egg
778 gevent-1.0-py2.7-linux-x86_64.egg
692 gevent_inotifyx-0.1.1-py2.7.egg
690 greenlet-0.4.2-py2.7-linux-x86_64.egg
687 gunicorn-18.0-py2.7.egg
707 hexagonit.recipe.download-1.6-py2.7.egg
712 hiredis-0.1.1-py2.7-linux-x86_64.egg
693 hl7-0.2.5-py2.7.egg
692 hl7apy-1.0.0-py2.7.egg
692 httplib2-0.8-py2.7.egg
693 huTools-0.63-py2.7.egg
744 imbox-0.5.5-py2.7.egg
750 Importing-1.10-py2.7.egg
698 inotifyx-0.2.0-py2.7-linux-x86_64.egg
698 iso8601-0.1.10-py2.7.egg
719 iw.recipe.cmd-0.3-py2.7.egg
708 jsonlib2-1.5.2-py2.7-linux-x86_64.egg
705 jsonpatch-1.5-py2.7.egg
705 jsonpointer-1.3-py2.7.egg
698 jsonschema-2.3.0-py2.7.egg
699 keyring-3.7-py2.7.egg
885 kombu-2.5.10-py2.7.egg
716 lxml-3.3.5-py2.7-linux-x86_64.egg
954 Mako-0.9.0-py2.7.egg
712 MarkupSafe-0.9.2-py2.7-linux-x86_64.egg
675 mccabe-0.2.1-py2.7.egg
674 memory_profiler-0.27-py2.7.egg
674 mixer-1.1.4-py2.7.egg
674 mock-1.0.1-py2.7.egg
674 netaddr-0.7.11-py2.7.egg
675 newrelic-2.20.0.17-py2.7-linux-x86_64.egg
675 nose-1.3.3-py2.7.egg
675 nose_cov-1.6-py2.7.egg
675 nosexcover-1.0.7-py2.7.egg
674 oauth-1.0.1-py2.7.egg
674 openerp_client_lib-1.1.2-py2.7.egg
686 ordereddict-1.1-py2.7.egg
677 oslo.config-1.2.1-py2.7.egg
686 outbox-0.1.8-py2.7.egg
680 paodate-1.2-py2.7.egg
680 parse-1.6.4-py2.7.egg
680 parse_type-0.3.4-py2.7.egg
714 Paste-1.7.5.1-py2.7.egg
692 pathtools-0.1.2-py2.7.egg
681 pbr-0.7.0-py2.7.egg
696 pep8-1.5.7-py2.7.egg
692 pesto-25-py2.7.egg
680 pg8000-1.10.2-py2.7.egg
976 pika-0.9.12-py2.7.egg
2496 pip-1.5.2-py2.7.egg
680 prettytable-0.7.2-py2.7.egg
836 psutil-2.1.0-py2.7-linux-x86_64.egg
662 psycogreen-1.0-py2.7.egg
662 psycopg2-2.5.3-py2.7-linux-x86_64.egg
662 pyaml-14.5.2-py2.7.egg
662 pyasn1-0.1.4-py2.7.egg
662 Py_Authorize-1.2.2.0-py2.7.egg
790 pycparser-2.10-py2.7.egg
1080 pycrypto-2.6-py2.7-linux-x86_64.egg
651 pyflakes-0.8.1-py2.7.egg
1013 Pygments-1.5-py2.7.egg
826 PyMySQL-0.6.2-py2.7.egg
762 pyOpenSSL-0.14-py2.7.egg
638 pyparsing-2.0.1-py2.7.egg
609 pyprof2calltree-1.1.0-py2.7.egg
608 pysolr-3.2.0-py2.7.egg
642 python_butler-0.9-py2.7.egg
732 python_dateutil-2.2-py2.7.egg
621 python_glanceclient-0.12.0-py2.7.egg
621 python_keyczar-0.71rc0-py2.7.egg
621 python_keystoneclient-0.6.0-py2.7.egg
621 python_novaclient-2.17.0-py2.7.egg
621 python_ntlm-1.0.1-py2.7.egg
620 python_openid-2.2.5-py2.7.egg
620 python_swiftclient-2.0.3-py2.7.egg
714 pytz-2014.4-py2.7.egg
754 PyYAML-3.11-py2.7-linux-x86_64.egg
905 pyzmq-2.2.0.1-py2.7-linux-x86_64.egg
590 pyzmq_static-2.2-py2.7.egg
591 raven-5.1.1-py2.7.egg
750 redis-2.9.1-py2.7.egg
588 repoze.lru-0.6-py2.7.egg
592 repoze.profile-2.0-py2.7.egg
1264 requests-2.6.0-py2.7.egg
590 requests_dump-0.1.3-py2.7.egg
590 requests_testadapter-0.3.0-py2.7.egg
590 requests_toolbelt-0.2.0-py2.7.egg
619 retools-0.3-py2.7.egg
679 rsa-3.1.2-py2.7.egg
672 sarge-0.1.3-py2.7.egg
575 sec_wall-1.2-py2.7.egg
584 setproctitle-1.1.6-py2.7-linux-x86_64.egg
699 setuptools-3.4.4-py2.7.egg
584 simpleflake-0.1.5-py2.7.egg
640 simplejson-3.3.0-py2.7-linux-x86_64.egg
578 simple_rbac-0.1.1-py2.7.egg
578 six-1.6.1-py2.7.egg
572 sortedcontainers-0.9.4-py2.7.egg
844 springpython-1.3.0rc1-py2.7.egg
1998 SQLAlchemy-0.9.9-py2.7-linux-x86_64.egg
561 stevedore-0.14.1-py2.7.egg
560 texttable-0.8.1-py2.7.egg
554 threadpool-1.2.7-py2.7.egg
604 tornado-2.4-py2.7.egg
566 translationstring-1.1-py2.7.egg
548 tzlocal-1.0-py2.7.egg
776 urllib3-1.5-py2.7.egg
542 warlock-1.1.0-py2.7.egg
543 watchdog-0.6.0-py2.7.egg
635 WebHelpers-1.3-py2.7.egg
536 Werkzeug-0.9.4-py2.7.egg
536 wrapt-1.6.0-py2.7-linux-x86_64.egg
536 xmltodict-0.9.0-py2.7.egg
545 zato_redis_paginator-1.0-py2.7.egg
561 zc.buildout-1.6.3-py2.7.egg
567 zc.recipe.egg-1.3.2-py2.7.egg
558 zerokspot.recipe.git-0.6.1-py2.7.egg

When running “strace -fttt /opt/zato/2.0.3/bin/zato” then I do see a a
point part mid-way where it takes a nearly 3 seconds allocating quite a
lot of memory. This appears to be just after loading pycparser.yacctab:

…
1429782977.184793
stat("/opt/zato/2.0.3/eggs/pycparser-2.10-py2.7.egg/pycparser/yacctab",
0x7ffcd3c2fd40) = -1 ENOENT (No such file or directory)
1429782977.185099
open("/opt/zato/2.0.3/eggs/pycparser-2.10-py2.7.egg/pycparser/yacctab.x86_64-linux-gnu.so",
O_RDONLY) = -1 ENOENT (No such file or directory)
1429782977.185295
open("/opt/zato/2.0.3/eggs/pycparser-2.10-py2.7.egg/pycparser/yacctab.so",
O_RDONLY) = -1 ENOENT (No such file or directory)
1429782977.186650
open("/opt/zato/2.0.3/eggs/pycparser-2.10-py2.7.egg/pycparser/yacctabmodule.so",
O_RDONLY) = -1 ENOENT (No such file or directory)
1429782977.186849
open("/opt/zato/2.0.3/eggs/pycparser-2.10-py2.7.egg/pycparser/yacctab.py",
O_RDONLY) = 9
1429782977.187038 fstat(9, {st_mode=S_IFREG|0644, st_size=122100, …}) = 0
1429782977.187219
open("/opt/zato/2.0.3/eggs/pycparser-2.10-py2.7.egg/pycparser/yacctab.pyc",
O_RDONLY) = 10
1429782977.187404 fstat(10, {st_mode=S_IFREG|0644, st_size=96295, …}) = 0
1429782977.187575 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11ac60f000
1429782977.187750 read(10,
"\3\363\r\nI\27\24Uc\0\0\0\0\0\0\0\0\t\1\0\0@\0\0\0s\20\24\1\0d\0"…,
4096) = 4096
1429782977.187938 fstat(10, {st_mode=S_IFREG|0644, st_size=96295, …}) = 0
1429782977.188157 read(10,
“dV\1d^\1d^\1d\352\1d\34\1d^\1d^\1d\305\0d\306\0d^\1d\307”…, 90112) =
90112
1429782977.190730 read(10, “-> INT_CONST_DECt\f\0\0\0p_constant_”…,
4096) = 2087
1429782977.190839 read(10, “”, 4096) = 0
1429782977.190900 brk(0x339f000) = 0x339f000
1429782977.191326 close(10) = 0
1429782977.191399 munmap(0x7f11ac60f000, 4096) = 0
1429782977.193834 brk(0x33c0000) = 0x33c0000
1429782977.199185 brk(0x33e1000) = 0x33e1000
1429782977.205476 brk(0x3402000) = 0x3402000
1429782977.207481 brk(0x3423000) = 0x3423000
1429782977.214815 brk(0x3444000) = 0x3444000
1429782977.218370 close(9) = 0
1429782977.221765 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5c09000
1429782977.223995 brk(0x3465000) = 0x3465000
1429782977.262286 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5bc9000
1429782977.413247 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5b89000
1429782977.415624 munmap(0x7f11a5b89000, 262144) = 0
1429782977.415836 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5b89000
1429782977.416029 munmap(0x7f11a5b89000, 262144) = 0
1429782977.416216 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5b89000
1429782977.511918 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5b49000
1429782977.590522 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5b09000
1429782977.598998 munmap(0x7f11a5b09000, 262144) = 0
1429782977.599427 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5b09000
1429782977.600731 munmap(0x7f11a5b09000, 262144) = 0
1429782977.603252 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5b09000
1429782977.685641 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5ac9000
1429782977.690817 munmap(0x7f11a5ac9000, 262144) = 0
1429782977.691078 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5ac9000
1429782977.691832 munmap(0x7f11a5ac9000, 262144) = 0
1429782977.692325 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5ac9000
1429782977.757838 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5a89000
1429782977.837528 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5a49000
1429782977.909125 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5a09000
1429782977.978442 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a59c9000
1429782978.031117 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5989000
1429782978.088378 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5949000
1429782978.136137 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5909000
1429782978.189428 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a58c9000
1429782978.244408 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5889000
1429782978.294405 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5849000
1429782978.357480 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5809000
1429782978.412987 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a57c9000
1429782978.461531 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5789000
1429782978.523824 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5749000
1429782978.568151 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5709000
1429782978.633716 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a56c9000
1429782978.677726 brk(0x3486000) = 0x3486000
1429782978.690366 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5689000
1429782978.746095 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5649000
1429782978.793317 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5609000
1429782978.846787 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a55c9000
1429782978.902806 brk(0x34a7000) = 0x34a7000
1429782978.905496 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5589000
1429782978.961034 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5549000
1429782979.011987 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5509000
1429782979.031515 brk(0x34e9000) = 0x34e9000
1429782979.064394 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a54c9000
1429782979.105983 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5489000
1429782979.166458 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5449000
1429782979.227586 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5409000
1429782979.227982 munmap(0x7f11a5409000, 262144) = 0
1429782979.228183 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5409000
1429782979.228371 munmap(0x7f11a5409000, 262144) = 0
1429782979.228601 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5409000
1429782979.228946 munmap(0x7f11a5409000, 262144) = 0
1429782979.229212 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5409000
1429782979.292950 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a53c9000
1429782979.345097 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5389000
1429782979.388502 brk(0x350a000) = 0x350a000
1429782979.409291 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5349000
1429782979.464578 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5309000
1429782979.518494 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a52c9000
1429782979.581330 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5289000
1429782979.608374 brk(0x352b000) = 0x352b000
1429782979.632635 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5249000
1429782979.689373 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5209000
1429782979.748937 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a51c9000
1429782979.790238 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5189000
1429782979.794926 munmap(0x7f11a5189000, 262144) = 0
1429782979.795281 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5189000
1429782979.795802 munmap(0x7f11a5189000, 262144) = 0
1429782979.796130 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5189000
1429782979.796340 munmap(0x7f11a5189000, 262144) = 0
1429782979.796545 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5189000
1429782979.839497 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5149000
1429782979.840641 munmap(0x7f11a5149000, 262144) = 0
1429782979.840807 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5149000
1429782979.868210 brk(0x3575000) = 0x3575000
1429782979.875197 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a5109000
1429782979.901888 mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11a50c9000
1429782979.942197 brk(0x35ac000) = 0x35ac000
1429782979.947095 brk(0x3648000) = 0x3648000
1429782979.949062 brk(0x36e4000) = 0x36e4000
1429782979.953170
stat("/opt/zato/2.0.3/eggs/cffi-0.8.2-py2.7-linux-x86_64.egg/cffi/verifier",
0x7ffcd3c30e30) = -1 ENOENT (No such file or directory)
1429782979.956859
open("/opt/zato/2.0.3/eggs/cffi-0.8.2-py2.7-linux-x86_64.egg/cffi/verifier.x86_64-linux-gnu.so",
O_RDONLY) = -1 ENOENT (No such file or directory)
1429782979.958121
open("/opt/zato/2.0.3/eggs/cffi-0.8.2-py2.7-linux-x86_64.egg/cffi/verifier.so",
O_RDONLY) = -1 ENOENT (No such file or directory)
1429782979.958853
open("/opt/zato/2.0.3/eggs/cffi-0.8.2-py2.7-linux-x86_64.egg/cffi/verifiermodule.so",
O_RDONLY) = -1 ENOENT (No such file or directory)
1429782979.959133
open("/opt/zato/2.0.3/eggs/cffi-0.8.2-py2.7-linux-x86_64.egg/cffi/verifier.py",
O_RDONLY) = 9
1429782979.959401 fstat(9, {st_mode=S_IFREG|0644, st_size=8756, …}) = 0
1429782979.960540
open("/opt/zato/2.0.3/eggs/cffi-0.8.2-py2.7-linux-x86_64.egg/cffi/verifier.pyc",
O_RDONLY) = 10
1429782979.960758 fstat(10, {st_mode=S_IFREG|0644, st_size=9218, …}) =
0…
…

but it goes on to load more libraries after this.

As far as I can see, pycparser isn’t even used by zato:

$ grep -R pycparser .
./code/buildout-darwin.cfg: pycparser
./code/buildout.cfg: pycparser
./code/versions.cfg:pycparser = 2.10

and loading it by itself doesn’t seem to take very long:

$ time /opt/zato/2.0.3/bin/py -m pycparser.yacctab

real 0m0.154s
user 0m0.130s
sys 0m0.020s

So I don’t really understand what’s happening.

Maybe giving it more than 1GB would help, as there is a small amount of
swap being used. However if I kill the zato server, so almost all RAM is
free, running “zato” by itself still takes 4.4 seconds:

$ time /opt/zato/2.0.3/bin/zato
usage: zato [-h] [–version]
{ca,check-config,component-version,create,decrypt,delete,encrypt,enmasse,info,from-config,migrate,quickstart,service,start,stop,update}
…
zato: error: too few arguments

real 0m4.404s
user 0m3.732s
sys 0m0.556s

Regards,

Brian.

forum-admin · June 20, 2016, 4:18pm

On 23/04/15 12:04, Brian Candler wrote:

I wonder if there is anything which can be done to reduce the zato
startup time?

Hi Brian,

1 GB is enough but it is disk I/O most likely that is causing it.

You are on a quickstart cluster so both of your servers are likely to
have 2 gunicorn workers + web-admin + LB and all of these processes
start in parallel competing for I/O.

I suggest starting them individually using ‘zato start’. Also, 4
gunicorn workers are probably too much if it’s only a VM for development

you can change it to 1 server with 1 gunicorn worker.

Then:

$ zato start /web/admin
(wait for OK)

$ zato start /load/balancer
(wait for OK)

$ zato start /the/only/server --fg
(you may want --fg anyway during development)

There are environments using 1 server with 1 worker + web-admin (no LB)
under as little as 256 MB of RAM for the whole OS and they work just
fine processing ~1M req/day so this is certainly doable.

I can see room for improvement in future - some parts could be lazily
loaded - but right now, can you try the above?

thanks,

forum-admin · June 20, 2016, 4:18pm

On 23/04/15 12:04, Brian Candler wrote:

However if I kill the zato server, so almost all RAM is free, running
"zato" by itself still takes 4.4 seconds:

Just for comparison, I have just installed a clean CentOS 6 under
VirtualBox in Ubuntu 14.04 and this is how it looks like:

[zato@centos6-64 ~]$ time zato --version
Zato 2.0.3.rev-281a9d29

real 0m1.284s
user 0m0.930s
sys 0m0.346s
[zato@centos6-64 ~]$ time zato --version
Zato 2.0.3.rev-281a9d29

real 0m1.276s
user 0m0.871s
sys 0m0.396s
[zato@centos6-64 ~]$ time zato --version
Zato 2.0.3.rev-281a9d29

real 0m1.287s
user 0m0.982s
sys 0m0.295s
[zato@centos6-64 ~]$ time zato --version
Zato 2.0.3.rev-281a9d29

real 0m1.292s
user 0m0.928s
sys 0m0.356s
[zato@centos6-64 ~]$ time zato --version
Zato 2.0.3.rev-281a9d29

real 0m1.284s
user 0m0.932s
sys 0m0.344s
[zato@centos6-64 ~]$ time zato --version
Zato 2.0.3.rev-281a9d29

real 0m1.284s
user 0m0.932s
sys 0m0.343s
[zato@centos6-64 ~]$ time zato --version
Zato 2.0.3.rev-281a9d29

real 0m1.282s
user 0m0.954s
sys 0m0.320s
[zato@centos6-64 ~]$

forum-admin · June 20, 2016, 4:18pm

On 23/04/2015 11:04, Brian Candler wrote:

Even at that point, the cluster is not functional. If I access
http://x.x.x.x:8183/zato/service/details?cluster=1 then for about 15
seconds I get ‘connection refused’. Then after that the connection is
accepted, but times out:
FYI, I have timed this now, by watching “ps” output.

After ./zato-qs-restart.sh has finished (which takes about 1 min 6
seconds), there is high CPU load from py and gunicorn processes. This
drops off after about 43 seconds. If I send a request over HTTP after
that point, it is answered immediately.

So the total restart time for zato is just short of 2 minutes on this
system - admittedly a single-CPU VM on a laptop - with a single server
and one gunicorn worker.

What this means for me is the following.

I can find no direct suppose in zato for unit testing of services or
TDD. That is, there appears to be no (documented) way of triggering the
request processing stack directly, e.g.

def MyClass(Service):
def handle(req):
…

def test_req():
dummy = “”"<s11:Envelope
…>s11:Body…</s11:Body>s11:Envelope"""
resp = invoke_soap_channel(MyClass, dummy)
assert resp …

To do this I’d have to build my own mock request object which would
involve duplicating bits of the zato stack, and hoping my mock request
accurately mirrors the properties of a Zato request.

So instead I’m writing my logic in a separate library, properly
tested, and then have a simple wrapper service to incorporate it into
zato: e.g.

from foo import receive_message
class ReceiveMessage(Service):
def handle(self):
with closing(self.outgoing.sql.get(OUT_SQL).session()) as db:
m = receive_message(db, self.request.raw_request,
channel_in=self.name,
remote_ip=self.wsgi_environ.get(“REMOTE_ADDR”, None))
self.response.payload = m.response
if m.error: self.response.status_code =
httplib.INTERNAL_SERVER_ERROR

(Aside: I’m taking the raw request, ignoring the Zato XML parsing of
SOAP requests, because I want to use xmltodict not lxml.objectify.
However I still use the SOAP channel so that Zato converts exceptions
into SOAP faults)

Since zato only hot-loads the service, not the library, I’m stuck with
a 2-minute reload cycle after making a change in the library before I
can try exercising it within zato

Regards,

Brian.