view · edit · sidebar · attach · print · history

Index>

20161212-davaz-load-test

Summary

  • Davaz.com must respond well with increased load
  • Port oddb.org to Ruby 2.3
  • Keep in Mind

Commits

Index

Davaz.com must respond well with increased load

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:

  • One must clear the cache (cookies) or davaz.com does show an error
  • Movies work, drawings and other stuff not
  • Visiting http://davaz.com/en/personal/inspiration/ gives an error 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?

Port oddb.org to Ruby 2.3

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

  • 10_de.oddb.org.conf using/usr/lib64/ruby/site_ruby/1.8/
  • ipn.ywesee.com.conf using /var/www/ipn.ywesee.com/lib
  • ydpm.ywesee.com.conf unsing /usr/lib64/ruby/site_ruby/1.8/

And on fastpower we lost many hours trying to make different rubies work under mod_ruby.

view · edit · sidebar · attach · print · history
Page last modified on December 12, 2016, at 07:31 PM