Zeno use the tool https://github.com/wg/wrk to measure how ch.oddb.org, davaz.com and steinweis.ch respond to load and remarked:
No problem with mod_ruby ruby 2.3.1 for wrk -t12 -c40000 -d30s http://www.davaz.com
No reaction (bit problems) with rack and ruby 2.3.1 when running wrk -t12 -c40000 -d30s http://www.steinwies.ch
There I do an emerge wrk here to and measure on oddb-ci2. Confirmed Zeno results here. Steinwies.ch no longer responds when wrk test is running and the number of request and of MBs transferred is a magnitude smaller. Details are
niklaus@oddb-ci2 ~> wrk -t12 -c40000 -d30s http://www.davaz.com
Running 30s test @ http://www.davaz.com
12 threads and 40000 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 22.70s 4.98s 28.67s 73.01%
Req/Sec 295.92 268.15 2.08k 71.16%
74538 requests in 29.95s, 108.71MB read
Socket errors: connect 24011, read 0, write 0, timeout 555729
Requests/sec: 2489.04
Transfer/sec: 3.63MB
niklaus@oddb-ci2 ~> wrk -t12 -c40000 -d30s http://www.steinwies.ch
Running 30s test @ http://www.steinwies.ch
12 threads and 40000 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 17.24s 5.55s 20.12s 88.60%
Req/Sec 11.30 5.19 32.00 85.39%
4095 requests in 30.11s, 12.15MB read
Socket errors: connect 24011, read 104, write 0, timeout 565346
Requests/sec: 136.00
Transfer/sec: 413.33KB
No testing againt steinwies.ngiger.ch (on the same host). Remarked that specifying a 5 second test produced meaningless results. Eg 0 requests/second.
Also I think that wrk is a necessary test that should give good results, but that it would not reflect the felt user experience as it only measures the time for a GET /. Once steinwies.ch and davaz.com pass the wrk test, we should use a modified tests which visits several pages. I must look at whether using a LUA script for wrk via the --script option would be easy to write.
As davaz.com does not have a hih load we decided to finish migration to Ruby 2.3.1 and rack.
Pushed commits:
Pulling the changes on fastpowerd, calling bundle install and restarting the services. Calling bundle installed failed on fastpower because of a compilation problem of mysql2
Using mime-types 3.1
Gem::Ext::BuildError: ERROR: Failed to build gem native extension.
current directory: /var/www/new.davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.5/ext/mysql2
/usr/local/bin/ruby231 -r ./siteconf20161212-3923-fakgpo.rb extconf.rb
checking for rb_absint_size()... no
checking for rb_absint_singlebit_p()... no
checking for ruby/thread.h... yes
checking for rb_thread_call_without_gvl() in ruby/thread.h... yes
checking for rb_thread_blocking_region()... yes
checking for rb_wait_for_single_fd()... yes
checking for rb_hash_dup()... yes
checking for rb_intern3()... yes
checking for rb_big_cmp()... yes
-----
Using mysql_config at /usr/bin/mysql_config
-----
checking for mysql.h... yes
checking for SSL_MODE_DISABLED in mysql.h... no
checking for MYSQL_OPT_SSL_ENFORCE in mysql.h... no
checking for errmsg.h... yes
checking for mysqld_error.h... yes
-----
Setting libpath to /usr/lib64/mysql
-----
creating Makefile
To see why this extension failed to compile, please check the mkmf.log which can be found here:
/var/www/new.davaz.com/vendor/ruby/2.3.0/extensions/x86_64-linux/2.3.0-static/mysql2-0.4.5/mkmf.log
current directory: /var/www/new.davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.5/ext/mysql2
make "DESTDIR=" clean
current directory: /var/www/new.davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.5/ext/mysql2
make "DESTDIR="
compiling client.c
compiling infile.c
compiling mysql2_ext.c
compiling result.c
compiling statement.c
statement.c: In function ‘my_big2ll’:
statement.c:218:3: warning: implicit declaration of function ‘RBIGNUM_LEN’ [-Wimplicit-function-declaration]
len = RBIGNUM_LEN(bignum) * SIZEOF_BDIGITS;
^
statement.c:218:31: error: ‘SIZEOF_BDIGITS’ undeclared (first use in this function)
len = RBIGNUM_LEN(bignum) * SIZEOF_BDIGITS;
^
statement.c:218:31: note: each undeclared identifier is reported only once for each function it appears in
statement.c: At top level:
cc1: warning: unrecognized command line option "-Wno-used-but-marked-unused"
cc1: warning: unrecognized command line option "-Wno-static-in-inline"
cc1: warning: unrecognized command line option "-Wno-reserved-id-macro"
cc1: warning: unrecognized command line option "-Wno-missing-variable-declarations"
cc1: warning: unrecognized command line option "-Wno-documentation-unknown-command"
cc1: warning: unrecognized command line option "-Wno-disabled-macro-expansion"
cc1: warning: unrecognized command line option "-Wno-covered-switch-default"
cc1: warning: unrecognized command line option "-Wno-conditional-uninitialized"
make: *** [statement.o] Error 1
make failed, exit code 2
Gem files will remain installed in /var/www/new.davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.5 for inspection.
Results logged to /var/www/new.davaz.com/vendor/ruby/2.3.0/extensions/x86_64-linux/2.3.0-static/mysql2-0.4.5/gem_make.out
An error occurred while installing mysql2 (0.4.5), and Bundler cannot continue.
Make sure that `gem install mysql2 -v '0.4.5'` succeeds before bundling.
Running sudo gem231 install mysql2 on fastpower returns the same error. On oddb-ci2 this command work without problem.
Adapting /etc/apache2/vhosts.d/davaz.com.conf. Createing service /service/davaz.com.rack/run with
#!/bin/sh exec 2>&1 cd /var/www/new.davaz.com exec sudo -u apache /usr/local/bin/bundle exec rackup config.ru
Why does the apache server not redirect correctly? Eg. visiting http://davaz.com/en/personal/home shows The requested URL /en/personal/home was not found on this server. Apache Server at davaz.com Port 80 Added the missing line RewriteEngine on in the apache conf.
Pushed commit Use mysql2 0.4.4. Add correct etc/davaz.com.conf.sample
Manual testing discovered the following errors:
RangeError at /en/personal/inspiration/0x003f8e3fe112b8 is recycled object Ruby /usr/local/lib/ruby/2.3.0/drb/drb.rb: in _id2ref, line 373
After getting this error I was unable to go back and continues to receive the error about recycles object.
Can I reproduce this error on oddb-ci2? On schnitzenthesen I run into this problem. I think I must call this error when initaalizing the @proxy variable in sbsm/app.rb call method. Adding a GC.start before to force garbage collection.
Looks as if adding the GC solved the problem, albeit at the cost of introducing 12 - 25 ms of additional delay. Therefore trying to call it after serving the request. NO: this is not easily possible. But which this approach, pages like drawings and schnitzenthesen only display all the images after a reload.
After changing the code to trace the @proxy and catch errors, I do not see the error nor the exception anymore. Must probably install a debug version of sbsm on fastpower to track this problem.
Running wrk to provoke errors was successfull and I found in log/2016/12/12/davaz_log many entries like
I, [2016-12-12T13:17:04.550402 #6056] INFO -- : session.rb:180:in `rescue in drb_process' Error in drb_process /var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.4/lib/mysql2/client.rb:107:in `_query' /var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.4/lib/mysql2/client.rb:107:in `block in query' /var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.4/lib/mysql2/client.rb:106:in `handle_interrupt' /var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.4/lib/mysql2/client.rb:106:in `query' /var/www/davaz.com/src/util/db_manager.rb:356:in `load_artobjects_links' /var/www/davaz.com/src/util/db_manager.rb:331:in `load_artobjects_by_artgroup' ::1 - - [12/Dec/2016:13:17:04 +0100] "GET / HTTP/1.1" 500 2644 0.0594
As all these error occurred within a mysql query statement I upgrade to the mysql2 gem 0.4.5(as there were similar looking items in https://github.com/brianmario/mysql2/releases ) and all theses errors when away the running wrk.
But after running wrk visiting and poking around I got under http://davaz.ngiger.ch/en/communication/links/ an error
NoMethodError at /en/communication/links/
undefined method `title' for #<DaVaz::Model::Link:0x007fd66c27b268>
<..>
/home/niklaus/git/sbsm/lib/sbsm/app.rb: in call
res = @proxy.drb_process(self, request)...
performance measured via wrk -t12 -c40000 -d30s http://davaz.ngiger.ch was: Requests/sec: 28.43
Now trying to use the GC.start
performance measured via wrk -t12 -c40000 -d30s http://davaz.ngiger.ch dropped to: Requests/sec: 15.42
But I still found mysql errors
D, [2016-12-12T13:51:03.005649 #5528] DEBUG -- : app.rb:98:in `call' starting session_id 1bd64ecab8fd936f2b80341b925 /: cookies davaz.com-preferences are {} @session CGI::Session @cgi CGI
I, [2016-12-12T13:51:03.005911 #5528] INFO -- : session.rb:180:in `rescue in drb_process' Error in drb_process /var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.5/lib/mysql2/client.rb:120:in `_query'
/var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.5/lib/mysql2/client.rb:120:in `block in query'
/var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.5/lib/mysql2/client.rb:119:in `handle_interrupt'
/var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.5/lib/mysql2/client.rb:119:in `query'
/var/www/davaz.com/src/util/db_manager.rb:604:in `load_serie_artobjects'
/var/www/davaz.com/src/util/db_manager.rb:591:in `block in load_series'
D, [2016-12-12T13:51:03.007479 #5528] DEBUG -- : app.rb:98:in `call' starting session_id 1c13891d563455fab8a52037751 /: cookies davaz.com-preferences are {} @session CGI::Session @cgi CGI
D, [2016-12-12T13:51:03.008729 #5528] DEBUG -- : app.rb:98:in `call' starting session_id 438a182d397d60c40423986d32 /: cookies davaz.com-preferences are {} @session CGI::Session @cgi CGI
But at least before and after running wrk my Chromium had not problem to visit davaz.ngiger.ch. Also remarked that while running wrk the time used for a GC.start went up to 50,60 or even 90 ms. It stayed at high 60 ms after stopping wrk and loading pages individually. htop (sorted by memory) show that apache serving davaz used around 6GB of memory (VIRT 6376, RES 239). After a restart of davaz, it used a lot less (VmPeak: 922540 kB as seen via /proc/$pid/status).
Pushed commit Prepare version 1.3.4 with GC before serving Rack calls
Checking on oddb-ci2 whether I get good result with this patch and mysql2 0.4.4. I get again mysql2 error which made pages like drawings to fail silently without loading all objects. A manual reload fixes this problem.
Trying to write my first lua script, which should visit the two pages "en/personal/work" and "en/works/paintings". The following snippet works
#!/usr/bin/lua
-------------------------------------------------------------
-- NOTE: each wrk thread has an independent Lua scripting
-- context and thus there will be one counter per thread
counter = 0
paths_to_visit = {"/en/personal/work", "/en/works/paintings"}
request = function()
counter = counter + 1
return wrk.format(nil, paths_to_visit[(counter % 2)+ 1])
end
Calling it with wrk -t2 -c10 -d30s --script=wrk_visit.lua http://davaz.ngiger.ch produces in /var/www/davaz.com/log/access_log entries like
::1 - - [12/Dec/2016:17:07:10 +0100] "GET /en/personal/work HTTP/1.1" 500 1654 "-" "-" ::1 - - [12/Dec/2016:17:07:10 +0100] "GET /en/works/paintings HTTP/1.1" 500 1654 "-" "-" ::1 - - [12/Dec/2016:17:07:10 +0100] "GET /en/works/paintings HTTP/1.1" 500 1654 "-" "-" ::1 - - [12/Dec/2016:17:07:10 +0100] "GET /en/personal/work HTTP/1.1" 500 1654 "-" "-" ::1 - - [12/Dec/2016:17:07:11 +0100] "GET /en/personal/work HTTP/1.1" 500 1654 "-" "-" ::1 - - [12/Dec/2016:17:07:11 +0100] "GET /en/works/paintings HTTP/1.1" 500 1654 "-" "-" ::1 - - [12/Dec/2016:17:07:11 +0100] "GET /en/personal/work HTTP/1.1" 500 1654 "-" "-" ::1 - - [12/Dec/2016:17:07:11 +0100] "GET /en/works/paintings HTTP/1.1" 500 1654 "-" "-" ::1 - - [12/Dec/2016:17:07:11 +0100] "GET /en/works/paintings HTTP/1.1" 500 1654 "-" "-" ::1 - - [12/Dec/2016:17:07:11 +0100] "GET /en/personal/work HTTP/1.1" 500 1654 "-" "-"
After running it visiting http://davaz.ngiger.ch/ produced the error
NoMethodError at /
undefined method `trans_handler=' for "MOV":String
Ruby /usr/local/lib/ruby/2.3.0/drb/drb.rb: in method_missing, line 1137
Web GET davaz.ngiger.ch/
Jump to:
GETPOSTCookiesENV
Traceback (innermost first)
/usr/local/lib/ruby/2.3.0/drb/drb.rb: in method_missing
return obj.__send__(msg_id, *a, &b)...
/home/niklaus/git/sbsm/lib/sbsm/app.rb: in call
Reverted fastpower to use the last commit tagged last_mod_ruby (1e548194e7975312359d20fddb82c52459593bc5). Copyied new apache.conf to /home/ngiger/davaz.com.conf.rack and restored the old content from /home/ngiger/davaz.com.conf.rack. Restarted apache and /service/davaz.com. Did a shutdown of/service/davaz.com.rack.
Improved check for @proxy by testing whether ir responds to :trans_handler. Now I am getting a more interesting error when loading http://davaz.ngiger.ch/en/works/multiples/ while wrk is running.
Mysql2::Error at /en/works/multiples/
This connection is in use by: #<Thread:0x007f904c129600@/usr/local/lib/ruby/2.3.0/webrick/server.rb:285 sleep>
Ruby /var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.4/lib/mysql2/client.rb: in _query, line 107
Web GET davaz.ngiger.ch/en/works/multiples/
Jump to:
GETPOSTCookiesENV
Traceback (innermost first)
/var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.4/lib/mysql2/client.rb: in _query
_query(sql, @query_options.merge(options))...
/var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.4/lib/mysql2/client.rb: in block in query
_query(sql, @query_options.merge(options))...
/var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.4/lib/mysql2/client.rb: in handle_interrupt
Thread.handle_interrupt(::Mysql2::Util::TimeoutError => :never) do...
/var/www/davaz.com/vendor/ruby/2.3.0/gems/mysql2-0.4.4/lib/mysql2/client.rb: in query
Thread.handle_interrupt(::Mysql2::Util::TimeoutError => :never) do...
/var/www/davaz.com/src/util/db_manager.rb: in load_artobjects_by_artgroup
result = connection.query(<<~SQL.gsub(/\n/, ''))...
/var/www/davaz.com/src/util/app.rb: in load_multiples
@db_manager.load_artobjects_by_artgroup('MUL')...
/var/www/davaz.com/src/state/works/multiples.rb: in init
multiples = @session.app.load_multiples...
/home/niklaus/git/sbsm/lib/sbsm/session.rb: in process
@state.init...
/home/niklaus/git/sbsm/lib/sbsm/session.rb: in block in drb_process
Which Rack middleware is the best for multithreading?
Before porting oddb.org to rack Zeno would like to use Ruby 2.3.1 under mod_ruby on thinpower. I am not sure whether this is a good idea because on thinpower we still have
And on fastpower we lost many hours trying to make different rubies work under mod_ruby.