trace by debug.gem
Rails for OpenBSD
Ruby On Rails 7.0 on OpenBSD 7.0
Template for a minimalistic ultra-secure server setup for your Ruby On Rails apps.
Choose OpenBSD for your Unix needs. OpenBSD -- the world’s simplest and
most secure Unix-like OS. An alternatve to the vulnerabilities and
overengineering of Linux and its related network services such as NGiNX/
Apache, OpenSSL, iptables/nftables, systemd, BIND, Postfix and much, much
more. OpenBSD -- the cleanest kernel, the cleanest userland and the
cleanest configuration syntax.
冒頭に説明が有るように、すっきりさっぱりのWEBシステム。足すのはrailsとpostgresSQLだけ。後はOpenBSDがデフォで用意してる素材を使ってる。
構成は、こうなってる。
httpd(8) (PDF: brief intro) and acme-client(8) are for Let’s Encrypt TLS-certificates and their ACME-challenges. relayd(8) does the reverse proxying and TLS-termination, and behind all that is Ruby On Rails’ Puma webserver, managed by rc.subr(8) system startup scripts. nsd(8) does the DNS, and pf(8) the firewalling.
痺れる程、素敵なシステムだ。でも、ちょいと使ってみるには大袈裟すぎる。標準の使いかたってかRailsの起動方法をメモしとく。
これがbundleを使う時の標準みたい。
vbox$ cat .bundle/config --- BUNDLE_PATH: "vendor/bundle"
railsをシステムエリアにインストール。それからアプリになるやつをblogて名前で構築。
doas gem install rails rails new blog : cd blog emacs Gemfile gem "puma", "~> 5.0", :git => 'https://github.com/puma/puma.git' # <= edit bundle install :
rails newすると、インストールが始まるけど、pumaの所でopensslがらみでエラーになる。githubから直送するように編集して、失敗した奴をインストール。
vbox$ bin/rails server -b 0.0.0.0 -p 8080
=> Booting Puma
=> Rails 7.0.2.4 application starting in development
=> Run `bin/rails server --help` for more startup options
Puma starting in single mode...
* Puma version: 5.6.4 (ruby 3.1.2-p20) ("Birdie's Version")
* Min threads: 5
* Max threads: 5
* Environment: development
* PID: 36040
* Listening on http://0.0.0.0:8080
vertulboxのポートフォワーディングのおかげで、Windows側ではlocalhostにアクセスするだけで、下記の日の丸もどきのRail印(svg)と共に、サーバーの素性が出て来た。
Rails version: 7.0.2.4
Ruby version: ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [i386-openbsd7.1]
blog配下で下記を実行すると、bundle exec .. が不要になるそうだ。
vbox$ bundle binstubs --path=vendor/bin `bundle binstubs` needs at least one gem to run.
vbox$ cat .bundle/config --- BUNDLE_BIN: "vendor/bin"
BAD knowhowだな。根がDSLだからしょうがない。
trace by rdbg
RailsのGemfileの一部。
source "https://rubygems.org"
git_source(:github) { |repo| "https://github.com/#{repo}.git" }
gem "puma", "~> 5.0", :git => 'https://github.com/puma/puma.git'
group :development do
# Use console on exceptions pages [https://github.com/rails/web-console]
gem "web-console"
# Add speed badges [https://github.com/MiniProfiler/rack-mini-profiler]
# gem "rack-mini-profiler"
# Speed up commands on slow machines / big apps [https://github.com/rails/spring]
# gem "spring"
end
何となく設定ファイルと理解出来るんだけど、rubyのスクリプトの断片とも見える。正体は何なの？ それに２行目を見ると、URLの文字列に、'.git' を追加してるっぽい。ならば、pumaを取りに行くとき、https://github.com/puma/puma.git.git と解釈されないか？ この設定で問題なく動いていたぞ。
という亊で、bundleがどう動くか、traceしてみたい。
データ採取
bundle initした後のGemfile に、gem 'profile' を指定。
vbox$ rdbg -c -- bundle install
[4, 13] in /opt/bin/bundle
4| #
5| # The application 'bundler' is installed as part of a gem, and
6| # this file is here to facilitate running it.
7| #
8|
=> 9| require 'rubygems'
10|
11| version = ">= 0.a"
12|
13| str = ARGV.first
=>#0 <main> at /opt/bin/bundle:9
(rdbg) trace call into: LOG # command
Enable CallTracer (enabled) into: LOG
(rdbg) c # continue command
Fetching gem metadata from https://rubygems.org/. ;; past about 17min
Resolving dependencies......
Using bundler 2.3.7
Fetching profile 0.4.0
Installing profile 0.4.0
Bundle complete! 1 Gemfile dependency, 2 gems now installed.
Bundled gems are installed into `./vendor/bundle`
LOG解析
i386の石だと18分近くかかって終了した。
vbox$ wc LOG 1411595 11703674 256772781 LOG
245Mものログサイズ。140万行とは、恐れいるな。 メソッドの入口と出口だけをログして、このサイズって亊は、lineでトレースしたらどうなるんだろう？
vbox$ head -5 LOG PID:15586 CallTracer (disabled) into: LOG DEBUGGER (trace/call) #th:1 #depth:3 > Gem.find_unresolved_default_spec at /EXTd/opt/lib/ruby/3.1.0/rubygems.rb:1219 DEBUGGER (trace/call) #th:1 #depth:4 > Hash#[] at /EXTd/opt/lib/ruby/3.1.0/rubygems.rb:1220 DEBUGGER (trace/call) #th:1 #depth:4 < Hash#[] #=> nil at /EXTd/opt/lib/ruby/3.1.0/rubygems.rb:1220 DEBUGGER (trace/call) #th:1 #depth:3 < Gem.find_unresolved_default_spec #=> nil at /EXTd/opt/lib/ruby/3.1.0/rubygems.rb:1222
とても１行が長過ぎて、見るに耐えない。前半の冗長部分は削除だな。
vbox$ cat LOG | sed -e 's!DEBUGGER (trace/call) #th:1 #depth!!' >SLOG
それじゃ、#th:1 だけを、抽出し不要な文字列を削除する。
vbox$ egrep ':2 ' SLOG :2 > Array#first at /opt/bin/bundle:13 :2 < Array#first #=> "install" at /opt/bin/bundle:13 :2 > String#b at /opt/bin/bundle:15 :2 < String#b #=> "install" at /opt/bin/bundle:15 :2 > String#[] at /opt/bin/bundle:15 :2 < String#[] #=> nil at /opt/bin/bundle:15 :2 > Kernel#respond_to? at /opt/bin/bundle:24 :2 < Kernel#respond_to? #=> true at /opt/bin/bundle:24 :2 > Gem.activate_bin_path at /EXTd/opt/lib/ruby/3.1.0/rubygems.rb:283 :2 < Gem.activate_bin_path #=> "/EXTd/opt/lib/ruby/gems/3.1.0/gems/bund... at /EXTd/opt/lib/ruby/3.1.0/rubygems.rb:290 :2 > Kernel#load at /opt/bin/bundle:25 DEBUGGER (trace/call) #th:3 #depth:2 > Bundler::Worker#process_queue at /EXTd/opt/lib/ruby/3.1.0/bundler/worker.rb:53 DEBUGGER (trace/call) #th:4 #depth:2 > Bundler::Worker#process_queue at /EXTd/opt/lib/ruby/3.1.0/bundler/worker.rb:53 DEBUGGER (trace/call) #th:4 #depth:2 < Bundler::Worker#process_queue #=> nil at /EXTd/opt/lib/ruby/3.1.0/bundler/worker.rb:59 DEBUGGER (trace/call) #th:3 #depth:2 < Bundler::Worker#process_queue #=> nil at /EXTd/opt/lib/ruby/3.1.0/bundler/worker.rb:59 DEBUGGER (trace/call) #th:5 #depth:2 > Bundler::Worker#process_queue at /EXTd/opt/lib/ruby/3.1.0/bundler/worker.rb:53 DEBUGGER (trace/call) #th:6 #depth:2 > Bundler::Worker#process_queue at /EXTd/opt/lib/ruby/3.1.0/bundler/worker.rb:53 DEBUGGER (trace/call) #th:5 #depth:2 < Bundler::Worker#process_queue #=> nil at /EXTd/opt/lib/ruby/3.1.0/bundler/worker.rb:59 DEBUGGER (trace/call) #th:6 #depth:2 < Bundler::Worker#process_queue #=> nil at /EXTd/opt/lib/ruby/3.1.0/bundler/worker.rb:59 :2 < Kernel#load #=> true at /opt/bin/bundle:25
ふむ、親のスレッドで全てを賄っているかと思ったら、違った。ネットへのアクセスは子供のスレッドに任せる黄金の法則が適用されているのだな。grepに -n を付けて、出現行番号を付けた方が、いいな。こうして、桁が消費されていく。広い画面な人はいいけど、ノーパソの年寄には辛いな。
vbox$ egrep '(#depth:2 |#depth:3 )' LOG | wc -l
138
vbox$ egrep '(#depth:2 |#depth:3 |#depth:4 )' LOG | wc -l
198
vbox$ egrep '(#depth:2 |#depth:3 |#depth:4 |#depth:5 )' LOG | wc -l
302
これだと、スレッドの区別をしていないな。各スレッドは均等に実行されてるのかな？
vbox$ egrep '#th:2' SLOG | wc -l
0
vbox$ egrep '#th:3' SLOG | wc -l
5520
vbox$ egrep '#th:4' SLOG | wc -l
12
vbox$ egrep '#th:5' SLOG | wc -l
882
vbox$ egrep '#th:6' SLOG | wc -l
64486
与えられた仕事により子供スレッドの働きにとんでも無い差がついてる。
そんじゃGemfile中に記述した'profile'がどのように扱われているか調べてみるか。
vbox$ grep profile SLOG :21< String#freeze #=> "gem \"profile\"\n" at /EXTd/opt/lib/ruby/3.1.0/bundler/dsl.rb:49 :21< String#freeze #=> "gem \"profile\"\n" at /EXTd/opt/lib/ruby/3.1.0/bundler/dsl.rb:49 : :48< String#split #=> ["action_profiler", "1.0.0", "02e4a593dd... at /EXTd/opt/lib/ruby/3.1.0/bundler/compact_index_client/cache.rb:56 :48< String#split #=> ["active-record-profiler", "0.1,1.0,1.1.... at /EXTd/opt/lib/ruby/3.1.0/bundler/compact_index_client/cache.rb:56
depthによって右にインデントしてくれるのは、時と場合によって、目障りだなあ。 それから、スクリプトのPATHも何とかして短縮出来無いか？
この場合はrdbgに頼るんじゃなくて、sedあたりを使って自前で書き換えだな。
vbox$ cat SLOG | sed -e 's#/EXTd/opt/lib/ruby/3.1.0/bundler#$BUN#' | \
sed -e 's/ * / /' >VSLOG
:30< String#<< #=> "GEM\n remote: https://rubygems.org/\n ... at $BUN/lockfile_generator.rb:63
返値の長さは、固定っぽいな。時と場合によってカスタマイズしたいな。
sakae@pen:/tmp/t$ cat LOG | sed -e 's#.*/\(.*.rb:.*\)#\1#' | head -30
basenameとdirnameを分離出来たら便利かな。上記はbasename用。こうして、出演スクリプト名を抽出して、TAGファイルを作成。後はスイスイとTAGジャンプする(by emacs)。あれ、ruby用のTAG作成機なんてあるかな？
ちょいと、お遊びで、使われているスクリプトのベスト10を出してみた。これdebian(64bit)の結果。環境によって結果は多いに異るな。
sakae@pen:/tmp/t$ cat LOG | sed -e 's#.*/\(.*.rb\):.*#\1#' | sort | uniq -c | sort -nr | head 695390 cache.rb 24307 common.rb 12040 version.rb 10012 specification.rb 7422 stub_specification.rb 6630 settings.rb 6458 kernel_require.rb 6168 requirement.rb 5844 tar_header.rb 5680 fileutils.rb
matsさんがパイプ言語を作っていたそうだけど、どうなったんだろう？ 仮に出来上がっていたとしても、rubyじゃ荷が重い。上記もコマンドを投入して、結果が得られるまで随分待たされるからね。
パイプの終端をwcに変更して、使われるスクリプト数を数えたら756種類と出てきた。こんなに沢山のスクリプトを使ってるの？ にわかに信じ難い。ああ、人に言えないBUGが混入してた。 sedは難しいとだけ言っておく。
debug.gem BUG?
2度目のbundle install を行って、子供のスレッドが動くか(動かないと思う)確認。
sakae@pen:/tmp/t$ grep -v '#th:1' ZZ
PID:1798 CallTracer (disabled) into: ZZ
([a-zA-Z][\-+.a-zA-Z\d]*)... at /usr/lib/ruby/2.7.0/uri/rfc2396_parser.rb:507
([a-zA-Z][\-+.a-zA-Z\d]*)... at /usr/lib/ruby/2.7.0/uri/rfc2396_parser.rb:507
(?:
(?:
... at /usr/lib/ruby/2.7.0/uri/rfc2396_parser.rb:508
(?:
(?:
... at /usr/lib/ruby/2.7.0/uri/rfc2396_parser.rb:508
:
^((?-mix: ){2}|(?-mix: ){4}|(?-m... at /var/lib/gems/2.7.0/gems/bundler-2.3.12/lib/bundler/lockfile_parser.rb:153
ruby\s
([\d.]+) # ruby ver... at /var/lib/gems/2.7.0/gems/bundler-2.3.12/lib/bundler/ruby_version.rb:52
こういう、見慣れないやつが出てきた。素のDebian環境。
sakae@pen:/tmp/t$ ruby -v
ruby 2.7.4p191 (2021-07-07 revision a21a3b7d23) [x86_64-linux-gnu]
sakae@pen:/tmp/t$ gem info debug
*** LOCAL GEMS ***
debug (1.5.0)
Author: Koichi Sasada
Homepage: https://github.com/ruby/debug
Licenses: Ruby, BSD-2-Clause
Installed at: /var/lib/gems/2.7.0
Debugging functionality for Ruby
下記は環境を変えてOpenBSD ruby 3.1.2p20 + debug 1.5.0 grepを行番号付きにしてみました。
1:PID:49794 CallTracer (disabled) into: LOG 112205: \A 112206: (\w+\.)? # optional... at /EXTd/opt/lib/ruby/3.1.0/bundler/settings.rb:487 114884: ^ 114885: (?:[ ]*-[ ]) # '- ' befo... at /EXTd/opt/lib/ruby/3.1.0/bundler/yaml_serializer.rb:35 114888: ^ 114889: ([ ]*) # indentations 114890: ... at /EXTd/opt/lib/ruby/3.1.0/bundler/yaml_serializer.rb:47 :
何となく正規表現にいじめられているような気がします。
patch
自分なりにdebug.gemを改造してみる。題材はfactなんだけど、なるべく現場に似せる為、無闇に長いPATHと長い関数名前にしてある。
vbox$ rdbg /tmp/deeeeeeeeeeeeepdir/longlongfact.rb
[1, 9] in /tmp/deeeeeeeeeeeeepdir/longlongfact.rb
=> 1| def longnamefact(n)
2| if n == 0
3| 1
4| else
5| n * longnamefact(n-1)
6| end
7| end
8|
9| longnamefact(40)
=>#0 <main> at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:1
(rdbg) trace call into: LOG # command
まずは、オリジナルな結果。
PID:40492 CallTracer (disabled) into: LOG DEBUGGER (trace/call) #th:1 #depth:2 > Object#longnamefact at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:1 DEBUGGER (trace/call) #th:1 #depth:3 > Integer#== at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:2 : DEBUGGER (trace/call) #th:1 #depth:40> Integer#- at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:5 DEBUGGER (trace/call) #th:1 #depth:40< Integer#- #=> 2 at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:5 DEBUGGER (trace/call) #th:1 #depth:40> Object#longnamefact at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:1 : DEBUGGER (trace/call) #th:1 #depth:3 < Integer#* #=> 8159152832478977343456112695961158942720... at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:5 DEBUGGER (trace/call) #th:1 #depth:2 < Object#longnamefact #=> 8159152832478977343456112695961158942720... at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:7
現場を再現出来たとしよう。。。 次は、軽く改造。
vbox$ diff -u tracer.rb.orig tracer.rb
--- tracer.rb.orig Mon Apr 25 15:09:35 2022
+++ tracer.rb Mon May 10 06:08:35 2022
@@ -43,7 +43,7 @@
end
def header depth
- "DEBUGGER (trace/#{@type}) \#th:#{Thread.current.instance_variable_get(:@__thread_client_id)} \#depth:#{'%-2d'%depth}"
+ "\#th:#{Thread.current.instance_variable_get(:@__thread_client_id)} \#dpt:#{'%-2d'%depth}"
end
def enable
@@ -119,7 +119,7 @@
next if skip?(tp)
depth = caller.size
- sp = ' ' * depth
+ sp = ' '
call_identifier_str =
if tp.defined_class
たったこれだけの改造(改悪)で、我ながら見易くなったと思うぞ。
PID:28696 CallTracer (disabled) into: ZZ #th:1 #dpt:2 > Object#longnamefact at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:1 #th:1 #dpt:3 > Integer#== at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:2 : #th:1 #dpt:40> Integer#- at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:5 #th:1 #dpt:40< Integer#- #=> 2 at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:5 #th:1 #dpt:40> Object#longnamefact at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:1 : #th:1 #dpt:3 < Integer#* #=> 8159152832478977343456112695961158942720... at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb:5 #th:1 #dpt:2 < Object#longnamefact #=> 8159152832478977343456112695961158942720... at /tmp/deeeeeeeeeeeeepdir/longlongfact.rb :7
返値が長いのは、どう対応すればいいの？ ああ、session.rb に有る SHORT_INSPECT_LENGTH = 40 が元ネタか。幾つにするのが適当か、悩ましいな。
factはtraceの実行例で必ず出てくるけど、本当の使い道は、順列・組み合わせを計算する時とかに利用されるんで、その亊を忘れるな。ついでに言うと負荷試験によく使われるfibなんてのは、深遠な自然を解明すると出て来る。これで本が何冊も書ける。NHK風に表現すると、数の沼だからね。
mruby
今迄見逃していた大事なものがあった。
mrubyのmは、何の略？ 普通に思い付くのはminiだな。ミリじゃ座りが悪いし、でも何となく micropythonに大きさの点で負けてしまうように思える。今度作るなら、nrubyが良いかも。 ナノって解釈すれば、マイクロよりはずっと小さい。newって解釈すれば、とても新しいって思える。
見所はクロスコンパイルの部分かな。取り敢えずのコンパイル。
vbox$ make
:
================================================
Config Name: host/mrbc
Output Directory: build/host/mrbc
Binaries: mrbc
Included Gems:
mruby-bin-mrbc - mruby compiler executable
mruby-compiler - mruby compiler library
================================================
極ありきたりだから、クロスの環境を用意するのもたやすいのかな。ラズパイが取り敢えずのターゲットになるか。持っていないけど。
vbox$ ldd bin/mruby
bin/mruby:
Start End Type Open Ref GrpRef Name
1748c000 37499000 exe 1 0 0 bin/mruby
046b3000 246b5000 rlib 0 1 0 /usr/lib/libm.so.10.1
01c0d000 21c1e000 rlib 0 1 0 /usr/lib/libc.so.96.1
0d4dd000 0d4dd000 ld.so 0 1 0 /usr/libexec/ld.so