Before activating the changes on ch.oddb.org I want to test the performance beforehand. I will run the old wrk based tests, too as I think the tests run yesterday do not reflect the real situation as no login was performed and there for most calls just have resulted in a "more than 5 request, do you want to login".
Unable to create a working login script for wrk and siege. Therefore installing rack based oddb.org on thinpower.
Using the following steps:
sudo -u apache bundle-240 exec rackup
sudo -u apache bundle-240 exec bin/crawler crawler
sudo -u apache bundle-240 exec bin/crawler google_crawler
Tests were not good, searching did not work and I got errors like "too many threads". Added a log for the rewrite into my Attach:20_oddb.org.conf.rack.txt.
Reverted to the old version. I think we should probably create a copy of /var/www/oddb.org and slowly migrate one flavour after the other to new rack to be able to pinpoint the errors.
Looking at how many times the different sites got visited.
cd /var/www/oddb.org ; grep -c GET log/*/2017/06/25/access_log log/anthroposophika/2017/06/25/access_log:6822 log/desitin/2017/06/25/access_log:1078 log/evidentia/2017/06/25/access_log:96 log/generika/2017/06/25/access_log:58887 log/homoeopathika/2017/06/25/access_log:9663 log/just-medical/2017/06/25/access_log:3795 log/mobile/2017/06/25/access_log:157863 og/oddb/2017/06/25/access_log:182695 log/oekk/2017/06/25/access_log:6297 log/phyto-pharma/2017/06/25/access_log:32582 log/santesuisse/2017/06/25/access_log:1816
Creating a working copy under /var/www/oddb.org.rack as root
Will test first we santesuisse.oddb.org. First search via Nolvadex worked. See
Updated the test/siege_url.txt to be able to test the santesuisse flavor. Running siege -v -t1m -f test/siege_urls.txt
returned
Lifting the server siege... Transactions: 693 hits Availability: 100.00 % Elapsed time: 59.47 secs Data transferred: 53.96 MB Response time: 0.65 secs Transaction rate: 11.65 trans/sec Throughput: 0.91 MB/sec Concurrency: 7.53 Successful transactions: 693 Failed transactions: 0 Longest transaction: 8.50 Shortest transaction: 0.08
In the /var/www/oddb.org.rack/log/santesuisse/2017/06/26/error_log I find afterwards
[Mon Jun 26 12:06:44 2017] [error] [client 80.218.53.88] (70007)The timeout specified has expired: proxy: error reading status line from remote server localhost:8012 [Mon Jun 26 12:06:44 2017] [error] [client 80.218.53.88] proxy: Error reading from remote server returned by /de/santesuisse/search/zone/drugs/search_query/Teva/search_type/st_company
Times to fetch nolvadex seem to increase when we run the tests
grep -w GET $PWD/log/2017/06/26/app_log | grep -i search | grep -i Nolvadex 80.218.53.88 - - [26/Jun/2017:11:49:25 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_oddb HTTP/1.1" 200 62999 12.2454 80.218.53.88 - - [26/Jun/2017:11:59:04 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.6353 80.218.53.88 - - [26/Jun/2017:11:59:10 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.4312 80.218.53.88 - - [26/Jun/2017:11:59:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.2416 80.218.53.88 - - [26/Jun/2017:12:02:43 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 11.3572 80.218.53.88 - - [26/Jun/2017:12:02:47 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 18.4853 80.218.53.88 - - [26/Jun/2017:12:02:48 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 11.3281 80.218.53.88 - - [26/Jun/2017:12:05:09 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 0.1817 80.218.53.88 - - [26/Jun/2017:12:05:10 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 0.7180 80.218.53.88 - - [26/Jun/2017:12:05:10 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.1878 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.3245 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.3500 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.4417 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.4929 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.5051 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.5796 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.5795 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.5953 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.7447 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.6264 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.6291 80.218.53.88 - - [26/Jun/2017:12:05:11 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 1.8510 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.3339 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.1885 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.2392 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.5127 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.2725 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.2310 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.0729 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.3313 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.3554 80.218.53.88 - - [26/Jun/2017:12:05:12 +0200] "GET /de/santesuisse/search/zone/drugs/search_query/Nolvadex/search_type/st_sequence HTTP/1.1" 200 28894 2.4055
And suddenly the process exited with
2017-06-26 12:06:49 +0200: Footprint exceeds 7168MB. Exiting. Exiting status. [2017-06-26 12:06:49] FATAL SystemExit: SystemExit /usr/local/ruby-2.4.0/lib/ruby/2.4.0/webrick/server.rb:171:in `select' /usr/local/ruby-2.4.0/lib/ruby/2.4.0/webrick/server.rb:171:in `block in start' /usr/local/ruby-2.4.0/lib/ruby/2.4.0/webrick/server.rb:33:in `start' /usr/local/ruby-2.4.0/lib/ruby/2.4.0/webrick/server.rb:158:in `start' /var/www/oddb.org.rack/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/handler/webrick.rb:34:in `run' /var/www/oddb.org.rack/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/server.rb:297:in `start' /var/www/oddb.org.rack/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/server.rb:148:in `start' /var/www/oddb.org.rack/vendor/ruby/2.4.0/gems/rack-2.0.3/bin/rackup:4:in `<top (required)>' /var/www/oddb.org.rack/vendor/ruby/2.4.0/bin/rackup:22:in `load' /var/www/oddb.org.rack/vendor/ruby/2.4.0/bin/rackup:22:in `<main>' NoMethodError undefined method `size' for nil:NilClass [2017-06-26 12:06:50] INFO going to shutdown ... undefined method `select_all' for nil:NilClass Did you mean? select 2017-06-26 12:07:01 +0200: Footprint exceeds 7168MB. Exiting. Exiting status.
Do we have a memory leak?
Changing the URL to read to exclude the (not really accessible company) and adding some searches for medical practitioner. Running the test for 15 minutes.
Had to change in src/util/oddbconfig.rb
the SERVER_URI = "druby://127.0.0.1:20000"
. Now while running the 15 minutes test I visiting http://santesuisse.oddb.org/ from my browser, neither from from oddb-ci2 nor from my debian machine takes a long time.
Got again another Memory exceeded after about 10 minutes.
Creating /service/ch.oddb.rack with log. Restarting a siege test for 15 minutes.
Remarked that the logging is quite excessive. Therefore looking on howto reduce it easily. E.g. by moving the most often called ones to the trace level.
Must debug the error NoMethodError undefined method `size' for nil:NilClass
. For this I launched the ruby rack with the -d (aka --debug option for ruby) using sudo -u apache RUBYOPT=-d bundle-240 exec rackup
. There I did see that I triggered it in src/util/oddbapp.rb line 2038.
Found the culprit. Fixing this error means also fixing the check that we exit the OddbAppp if we have too many open sessions. Pushed the commits
Release SBSM 1.4.7
Running siege again for 15 minutes against santesuisse.oddb.orgl. No it finished the 15 minutes, but I see in the service log
@400000005951160136de8c04 Did you mean? select @400000005951160139d8b54c undefined method `select_all' for nil:NilClass
I am able to find a few searches, which take quite some time
egrep "GET .*\/show" log/2017/06/26/app_log | cut -d ' ' -f11 | sort -n 52.8593 73.1830
But why did we get the select_all. Trying again with RUBYOPTS=-d I get
Exception `NoMethodError' at /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/connection_pool.rb:39 - undefined method `select_all' for nil:NilClass Did you mean? select undefined method `select_all' for nil:NilClass Did you mean? selectException `NoMethodError' at /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/connection_pool.rb:39 - undefined method `select_all' for nil:NilClass
Placed a manual breakpoint there and got the following backtrace
[2] pry(#<ODBA::ConnectionPool>)> backtrace undefined method `select_one' for nil:NilClass Did you mean? select NameError: undefined method `odba_receiver' for class `Hash' Did you mean? odba_extent (eval):2:in `method' (eval):2:in `method' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/frame.rb:171:in `ruby_args' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/frame.rb:68:in `args' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/frame.rb:93:in `deco_args' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/frame.rb:110:in `deco_call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/frame.rb:152:in `to_hash' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/commands/where.rb:45:in `block in print_backtrace' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/printers/base.rb:58:in `block in array_of_args' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/printers/base.rb:57:in `each' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/printers/base.rb:57:in `with_index' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/printers/base.rb:57:in `each_with_object' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/printers/base.rb:57:in `array_of_args' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/printers/plain.rb:16:in `print_collection' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/commands/where.rb:44:in `print_backtrace' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/commands/where.rb:38:in `execute' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/pry-byebug-3.4.2/lib/byebug/processors/pry_processor.rb:121:in `perform_backtrace' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/pry-byebug-3.4.2/lib/byebug/processors/pry_processor.rb:54:in `perform' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/pry-byebug-3.4.2/lib/byebug/processors/pry_processor.rb:35:in `run' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/pry-byebug-3.4.2/lib/byebug/processors/pry_processor.rb:111:in `resume_pry' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/pry-byebug-3.4.2/lib/byebug/processors/pry_processor.rb:63:in `at_line' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/byebug-9.0.6/lib/byebug/context.rb:96:in `at_line' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/connection_pool.rb:43:in `rescue in method_missing' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/connection_pool.rb:37:in `method_missing' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/storage.rb:62:in `bulk_restore' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:56:in `bulk_fetch' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:261:in `fetch_collection' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:633:in `restore' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:319:in `block in fetch_or_restore' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:314:in `fetch_or_do' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:318:in `fetch_or_restore' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:641:in `restore_object' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:606:in `load_object' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:227:in `block in fetch' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:314:in `fetch_or_do' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/cache.rb:226:in `fetch' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/stub.rb:49:in `odba_receiver' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/odba-1.1.2/lib/odba/stub.rb:112:in `method_missing' /var/www/oddb_rack.org/src/util/oddbapp.rb:1334:in `sorted_fachinfos' /var/www/oddb_rack.org/src/util/oddbapp.rb:1577:in `method_missing' /var/www/oddb_rack.org/src/state/drugs/init.rb:19:in `init' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/sbsm-1.4.7/lib/sbsm/session.rb:414:in `logout' /var/www/oddb_rack.org/src/util/session.rb:149:in `logout' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/sbsm-1.4.7/lib/sbsm/session.rb:252:in `block in process_rack' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/sbsm-1.4.7/lib/sbsm/session.rb:236:in `synchronize' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/sbsm-1.4.7/lib/sbsm/session.rb:236:in `process_rack' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/sbsm-1.4.7/lib/sbsm/app.rb:122:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/lint.rb:49:in `_call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/lint.rb:37:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/show_exceptions.rb:23:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/content_length.rb:15:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/static.rb:149:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/common_logger.rb:33:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/tempfile_reaper.rb:15:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/lint.rb:49:in `_call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/lint.rb:37:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/show_exceptions.rb:23:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/common_logger.rb:33:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/chunked.rb:54:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/content_length.rb:15:in `call' /var/www/oddb_rack.org/vendor/ruby/2.4.0/gems/rack-2.0.3/lib/rack/handler/webrick.rb:86:in `service' /usr/local/ruby-2.4.0/lib/ruby/2.4.0/webrick/httpserver.rb:140:in `service' /usr/local/ruby-2.4.0/lib/ruby/2.4.0/webrick/httpserver.rb:96:in `run' /usr/local/ruby-2.4.0/lib/ruby/2.4.0/webrick/server.rb:290:in `block in start_thread'
What is going on here? @sorted_fachinfos is an element of the ODBA_EXCLUDE_VARS-array in oddbapp.rb. Does this mean, that it never should be passed to the odba cache?