trace by debug.gem (2)
trace (call or line)
ふとdebug.gemのトレース機構にはcallの他にlineも有った亊を思い出した。どんな違いが有るか比べてみる亊にした。
外観比較
まずは、出来上がったログファイルのサイズ比較だな。
ob$ wc LOG* 1415163 8896921 165157996 LOGcall 449635 1798541 35993396 LOGline
圧倒的にlineの方が小さい。callは入口と出口でログされるから、line毎に比べて２倍の差が付くと予想してたんだけど、３倍近くになった。なんで？
ob$ head LOGline PID:36350 LineTracer (disabled) into: LOGline #th:1 #dpt:3 at /usr/local/lib/ruby/3.1/rubygems.rb:1220 #th:1 #dpt:3 at /usr/local/lib/ruby/3.1/rubygems.rb:1221 #th:1 #dpt:3 at /usr/local/lib/ruby/3.1/rubygems/specification.rb:1254 #th:1 #dpt:1 at /usr/local/bin/bundle:11
これ、すっきりしてるから、登場スクリプトを抽出するには便利そう。
ob$ head LOGcall
PID:30131 CallTracer (disabled) into: LOGcall
#th:1 #dpt:3 > Gem.find_unresolved_default_spec at /usr/local/lib/ruby/3.1/rubygems.rb:1219
#th:1 #dpt:4 > Hash#[] at /usr/local/lib/ruby/3.1/rubygems.rb:1220
#th:1 #dpt:4 < Hash#[] #=> nil at /usr/local/lib/ruby/3.1/rubygems.rb:1220
#th:1 #dpt:3 < Gem.find_unresolved_default_spec #=> nil at /usr/local/lib/ruby/3.1/rubygems.rb:1222
#th:1 #dpt:3 > Gem::Specification.unresolved_deps at /usr/local/lib/ruby/3.1/rubygems/specification.rb:1253
#th:1 #dpt:3 < Gem::Specification.unresolved_deps #=> {} at /usr/local/lib/ruby/3.1/rubygems/specification.rb:1255
#th:1 #dpt:2 > Array#first at /usr/local/bin/bundle:13
exec time
次は、実行時間にどれぐらい差が有るか？ ログファイルのstatを出してみた。ファイルの作成時刻やら更新時刻やらが出てくるので、その差を取れば、実行時間になるな。下記は、見やすいように、行に展開した。
ob$ stat LOGcall 65280 51458 -rw-r--r-- 1 sakae wheel 206640 165157996 "May 11 14:03:32 2022" "May 11 14:15:01 2022" "May 11 14:15:01 2022" 8192 322752 0 LOGcall
で、不合理な時間差の計算ですよ。そういうのはコンピュータに押し付けてしまうのが良い。
irb(main):001:0> require 'time'
=> true
irb(main):002:0> st = Time.rfc2822('11 May 2022 14:03:32 +0900')
=> 2022-05-11 14:03:32 +0900
irb(main):003:0> sp = Time.rfc2822('11 May 2022 14:15:01 +0900')
=> 2022-05-11 14:15:01 +0900
irb(main):004:0> sp - st
=> 689.0
拡張ライブラリィーのtimeを入れると、RFC2822とかHTTP-date形式が扱えるようになる。 そのうちのrfc形式の方がオイラーには優しく写ったので使ってみた。文字列をTimeオブジェクトに変換するんだね。例では日付の前に曜日がツイているけど、無くてもOK。TZは飾りだけど、一応付けておかないと、エラーになる。
ob$ stat LOGline 65280 128642 -rw-r--r-- 1 sakae wheel 514128 35993396 "May 11 13:59:14 2022" "May 11 13:50:46 2022" "May 11 13:50:46 2022" 8192 70368 0 LOGline ob$ stat -r LOGline 65280 128642 0100644 1 1000 0 514128 35993396 1652245154 1652244646 1652244646 8192 70368 0 LOGline
実はstatにはrawモードが用意されてる。んで、それを見ればTimeオブジェクトの正体が一発で判明する。
irb(main):001:0> 1652244646 - 1652245154 => -508 irb(main):002:0> 508 / 60 => 8
which script use ?
ob$ cat LOGline | sed -e 's#.* at \(/.*\):.*#\1#' | sort | uniq -c | sort -nr | head 350391 /usr/local/lib/ruby/3.1/bundler/compact_index_client/cache.rb 8184 /usr/local/lib/ruby/3.1/rubygems/version.rb 5740 /usr/local/lib/ruby/3.1/rubygems/stub_specification.rb 5173 /usr/local/lib/ruby/3.1/psych/visitors/to_ruby.rb 4755 /usr/local/lib/ruby/3.1/psych/tree_builder.rb 3588 /usr/local/lib/ruby/3.1/rubygems/specification.rb 3067 /usr/local/lib/ruby/3.1/rubygems/requirement.rb 2904 /usr/local/lib/ruby/3.1/rubygems/resolver.rb 2735 /usr/local/lib/ruby/3.1/rubygems/resolver/molinillo/lib/molinillo/resolution.rb 2390 /usr/local/lib/ruby/3.1/rubygems/platform.rb
行き成りGemfileなんてのがアクセス・ランキングに出て来たんで、その前後を確認。やっぱりdslなんだな。
ob$ grep '/tmp/t/Gemfile' -n -C 4 LOGline LOGline-47952-#th:1 #dpt:19 at /usr/local/lib/ruby/3.1/bundler/dsl.rb:49 LOGline-47953-#th:1 #dpt:21 at /usr/local/lib/ruby/3.1/bundler/dsl.rb:49 LOGline:47954:#th:1 #dpt:21 at /tmp/t/Gemfile:3 LOGline-47955-#th:1 #dpt:22 at /usr/local/lib/ruby/3.1/bundler/plugin/dsl.rb:40 LOGline-47956-#th:1 #dpt:22 at /usr/local/lib/ruby/3.1/bundler/plugin/dsl.rb:41 -- LOGline-48245-#th:1 #dpt:24 at /usr/local/lib/ruby/3.1/bundler/source_list.rb:73 LOGline-48246-#th:1 #dpt:25 at /usr/local/lib/ruby/3.1/bundler/source_list.rb:12 LOGline:48247:#th:1 #dpt:21 at /tmp/t/Gemfile:5 LOGline-48248-#th:1 #dpt:22 at /usr/local/lib/ruby/3.1/bundler/plugin/dsl.rb:36 LOGline-48249-#th:1 #dpt:19 at /usr/local/lib/ruby/3.1/bundler/dsl.rb:57
BUG?の正体見たり
少し知恵を働かせて、grepと協調動作をさせてみた。分かり易い例を挙げる。
sakae@pen:/tmp/t$ grep -n -v '#th:1' -C 2 LOGcall | cut -b -120 : -- 113266-#th:1 #dpt:34> Kernel#freeze at /var/lib/gems/2.7.0/gems/bundler-2.3.12/lib/bundler/ruby_version.rb:52 113267-#th:1 #dpt:34< Kernel#freeze #=> / 113268: ruby\s 113269: ([\d.]+) # ruby ver... at /var/lib/gems/2.7.0/gems/bundler-2.3.12/lib/bundler/ruby_version.rb:52 113270-#th:1 #dpt:34> Module#private at /var/lib/gems/2.7.0/gems/bundler-2.3.12/lib/bundler/ruby_version.rb:113 113271-#th:1 #dpt:34< Module#private #=> Bundler::RubyVersion at /var/lib/gems/2.7.0/gems/bundler-2.3.12/lib/bundler/ru
該当するソースを閲覧。
ruby_version.rb
46 # @private 47 PATTERN = / 48 ruby\s 49 ([\d.]+) # ruby version 50 (?:p(-?\d+))? # optional patchlevel 51 (?:\s\((\S+)\s(.+)\))? # optional engine info 52 /xo.freeze
正規表現が返値として表示されてるだけ。幽霊の正体見たり、枯れすすき だったんですね。どうもお騒がせしました。まて、正規表現を文字列化するのが正解だろう。そんなメソッド知らないけど。
少しは反省しろよ。そうでないと、近頃のマスコミのように、自分の都合が良い部分だけを取出して、大騒ぎしてしまう輩になってしまうぞ。
sakae@pen:/tmp/t$ irb irb(main):001:0/ pat = /abc irb(main):002:0/ def/ => /abc ... irb(main):003:0> p pat /abc def/ => /abc def/ irb(main):004:0> p pat.to_s "(?-mix:abc\ndef)" => "(?-mix:abc\ndef)"
irbが勝手に推測して、候補を出してきてくれた。まあ、 to_s って、誰でも思いつくけど。
TAGS for emacs
折角なので、emacs用のTAGSを作ってみる。題材は２回目のbundle install のline traceのログ。
vbox$ cat LOG | sed -e 's#.* at \(/.*\):.*#\1#' >SLOG vbox$ cat SLOG | sort | uniq >ULOG vbox$ emacs ULOG vbox$ etags `cat ULOG`
ファイル名だけを取出し。ユニークなファイル名にまとめ。ゴミが多少混っているので除去。それを元にTAGSを作成。ファイル数が253ヶだったよ。
これでスイスイ行くはずなんだけど、、、、
/EXTd/opt/lib/ruby/3.1.0/bundler/vendor/uri/lib/uri/common.rb 18: RFC3986_PARSER /EXTd/opt/lib/ruby/3.1.0/bundler/vendor/uri/lib/uri/rfc3986_parser.rb 3: class RFC3986_Parser /EXTd/opt/lib/ruby/3.1.0/uri/common.rb 18: RFC3986_PARSER /EXTd/opt/lib/ruby/3.1.0/uri/rfc3986_parser.rb 3: class RFC3986_Parser
今のコンテキストが分っていないと、どれをみたらいいか迷うぞ。rdbgで案内してもらうのが楽でいいか。
でも、まあ、オーダーメードのTAGが簡単に作れる亊が分ったから佳とするか。但し、コンタミネーション(異物混入)には注意。まあ、医療分野みたいですから。
stat
上で出て来たstatを少し探検してみる。ソースが有るから、思い立ったら吉日さ。
manによると、Version 1 AT&T UNIX で掲載され Version 4 AT&T UNIXで消えて、 NetBSD 1.6で再登場。数奇な運命に翻弄されてる。
核は、 stat(2) を実行して、表示する亊だ。ファイルのメタ情報なんだな。
struct stat {
dev_t st_dev; /* inode's device */
ino_t st_ino; /* inode's number */
mode_t st_mode; /* inode protection mode */
nlink_t st_nlink; /* number of hard links */
uid_t st_uid; /* user ID of the file's owner */
gid_t st_gid; /* group ID of the file's group */
dev_t st_rdev; /* device type */
struct timespec st_atim; /* time of last access */
struct timespec st_mtim; /* time of last data modification */
struct timespec st_ctim; /* time of last file status change */
off_t st_size; /* file size, in bytes */
blkcnt_t st_blocks; /* blocks allocated for file */
blksize_t st_blksize; /* optimal blocksize for I/O */
u_int32_t st_flags; /* user defined flags for file */
u_int32_t st_gen; /* file generation number */
};
srcと対面
久し振りにソースを開いてみる。
#define SHELL_FORMAT \
"st_dev=%d st_ino=%i st_mode=%#p st_nlink=%l " \
"st_uid=%u st_gid=%g st_rdev=%r st_size=%z " \
"st_atime=%a st_mtime=%m st_ctime=%c " \
"st_blksize=%k st_blocks=%b st_flags=%f"
#define LINUX_FORMAT \
" File: \"%N\"%n" \
" Size: %-11z FileType: %HT%n" \
" Mode: (%01Mp%03OLp/%.10Sp) Uid: (%5u/%8Su) Gid: (%5g/%8Sg)%n" \
"Device: %Hd,%Ld Inode: %i Links: %l%n" \
"Access: %Sa%n" \
"Modify: %Sm%n" \
"Change: %Sc"
まず目についたのが、これ。BSDなシステムなのにリナ風にも表示出来るのか。ソースに埋め込んであるだけじゃなくて、もっと宣伝してあげればいいのに。と言う亊で、どんなスイッチでこのフォーマットを使うか、調べてみるね。
case 'x':
statfmt = LINUX_FORMAT;
if (timefmt == NULL)
timefmt = "%c";
break;
該当するmanの所を見ると、
-x Display information in a more verbose way.
何とまあ、控えめだ亊。それとも表立って Linuxと書きたくなかったか。
case SHOW_st_atime:
gottime = 1;
secs = st->st_atime;
nsecs = st->st_atimensec;
/* FALLTHROUGH */
アクセスタイムなんかもnsecの分解能で保持してるのか。これもそれも、きっとファイナンス部門の高速取引からの要求なんだろね。何だか、世の中せせこましいな。
kernel side
ファイルに対する操作をした時、どの様に反応するか、見ておく。
vm$ date; touch aa Fri May 13 05:42:20 JST 2022 vm$ echo now `date` >>aa vm$ date; cat aa Fri May 13 05:44:01 JST 2022 now Fri May 13 05:43:19 JST 2022 vm$ date; chmod 600 aa Fri May 13 05:44:53 JST 2022 vm$ stat -x aa File: "aa" Size: 33 FileType: Regular File Mode: (0600/-rw-------) Uid: ( 1000/ sakae) Gid: ( 1000/ sakae) Device: 0,0 Inode: 112682 Links: 1 Access: Fri May 13 05:44:01 2022 Modify: Fri May 13 05:43:19 2022 Change: Fri May 13 05:44:53 2022
そしてカーネル側へ。lstatなんてのも有るようだけど、まずは本流でチェック。
int
sys_stat(struct proc *p, void *v, register_t *retval)
{
struct sys_stat_args /* {
syscallarg(const char *) path;
syscallarg(struct stat *) ub;
B => } */ *uap = v;
return (dofstatat(p, AT_FDCWD, SCARG(uap, path), SCARG(uap, ub), 0));
}
実質は、 vfs_syscalls.c に丸投げ。
dofstatat(struct proc *p, int fd, const char *path, struct stat *buf, int flag)
{
struct stat sb;
int error, follow;
struct nameidata nd;
:
if ((error = namei(&nd)) != 0)
return (error);
=> error = vn_stat(nd.ni_vp, &sb, p);
vput(nd.ni_vp);
vn_stat を通過した所で、結果を確認。
(gdb) p sb
$12 = {
st_mode = 33133,
st_dev = 0,
st_ino = 52439,
st_nlink = 1,
st_uid = 0,
st_gid = 7,
st_rdev = 256720,
st_atim = {
tv_sec = 1652389270,
tv_nsec = 220699342
},
st_mtim = {
tv_sec = 1570899143,
tv_nsec = 0
},
st_ctim = {
tv_sec = 1581317013,
tv_nsec = 864459906
},
st_size = 13964,
st_blocks = 28,
st_blksize = 16384,
st_flags = 0,
st_gen = 1339754254,
__st_birthtim = {
tv_sec = 0,
tv_nsec = 0
}
}
思わせぶりな __st_birthtim なんてのが有るなあ。使われてはいないようだけど。
stat of Linux
リナでも潜れればいいんだけど、環境作りがとても大変なので諦め。代わりに今使ったOpenBSDのdisk-imageをstatして、お茶を濁しておく。
sakae@pen:~/sim/i386$ stat disk File: disk Size: 887160832 Blocks: 1732744 IO Block: 4096 regular file Device: 801h/2049d Inode: 1066059 Links: 1 Access: (0644/-rw-r--r--) Uid: ( 1000/ sakae) Gid: ( 1000/ sakae) Access: 2022-05-13 06:29:00.380652972 +0900 Modify: 2022-05-13 06:29:07.816730319 +0900 Change: 2022-05-13 06:29:07.816730319 +0900 Birth: 2020-03-02 07:03:59.258217893 +0900