man-pages 4.09 のリリース

ちょっと前から linux-man の ML を読み始めたのだけど、 man-pages 4.09 のリリースがお知らせされていた

linux-man-pages.blogspot.jp

リリースの内容

詳細はリンク先をみてもらえばよいが、更新内容は Linux Kernel 4.9 で追加された新しいシステムコールを対象にした man もあれば、新しいものに限らず下のように広範なトピックがはいっている。コミットだけで見ると typo fix やスタイル調整も結構な量があるようだ

自分の関心をひいたのは以下の更新

A new pkey_alloc(2) page, written by Dave Hansen, documents the pkey_alloc() and pkey_free() system calls added in Linux 4.9.

4.9 で追加された pkey_alloc(2) 共有ホスティングのようなとこで何か利用できないか? (e.g. mod_process_security )

A new fuse(4) page, written by Keno Fischer, partially documents the /dev/fuse device.

/dev/fuse について。ここ最近、社内外で fuse をハックした実装をよく見かけていたが /dev/fuse そのもの実装をおいたかったのでタイムリ

A new sock_diag(7) page, written by Pavel Emelyanov and Dmitry V. Levin, documents the NETLINK_SOCK_DIAG interface.

sock_diag(7) - Linux manual page socket の内部情報を取るための NETLINK_SOCK_DIAG インタフェースについて。UNIX ドメインソケットのバックログサイズを netlink インタフェースで計測してみたかったのだけど使い方がわからず頓挫していた調査があったので、これもタイムリ

A new tmpfs(5) page, written by me, provides an overview of the tmpfs filesystem.

tmpfs について。内部実装は System V 共有メモリの anon なページの mmap(2) でも使われている点への言及など

リリースの間隔

man-pages の過去リリースを見ると、 kernel のマイナーバージョン更新 (今回は 4.8 -> 4.9 ) にタイミングを合わせているよな感じ

kernel man-pages
4.9 - Sun, 11 Dec 2016 4.09 - Mon, 12 Dec 2016
4.8 - Sun, 2 Oct 2016 4.08 - Sat, 8 Oct 2016
4.7 - Sun, 24 Jul 2016 4.07 - Sun, 17 Jul 2016
4.6 - Sun, 15 May 2016 4.06 - Wed, 11 May 2016

📝 バージョニングも揃ってるぽいので、後で過去ログを調べてみよう

man-pages のメンテナについて

このエントリを書くまで認知していなかったのだが、 man-pages のメンテンナである Michael Kerrisk さんは 『Linuxプログラミングインタフェース』本の著者でもあって「ああ なるほど」である

Linuxプログラミングインタフェース

Linuxプログラミングインタフェース

厚い

デバッグ: gdb で ruby のバックトレースを自動で採取

とある Rails / Unicorn サーバで perf top を眺めていたら、やたらと bcrypt_ext.soBF_crypt が高いオーバーヘッドを示しているのを発見した。ひゃぁ

Samples: 168K of event 'cycles', Event count (approx.): 50386752987
Overhead  Shared Object             Symbol
  36.61%  bcrypt_ext.so             [.] BF_crypt 🔥
   7.83%  ruby                      [.] vm_exec_core
   3.66%  ruby                      [.] st_lookup
   3.55%  ruby                      [.] mix_id_table_lookup
   2.44%  ruby                      [.] vm_search_method.isra.79
   1.87%  libc-2.17.so              [.] _int_malloc

gdb で調査

BF_crypt の呼び出し元を探るべく gdbunicorn にアタッチして rb_backtrace() でバックトレースを採取するのを試行錯誤していたが、ブレークする度にリクエストを止めていることに気がついたのでこりゃマズいと、採取方法を変えた。

gdb で調査

command を使って自動化した

$ sudo gdb -p <unicorn の pid>

(gdb) b BF_crypt
Breakpoint 1 at 0x7f8452663350: file crypt_blowfish.c, line 569.

(gdb) command 1
Type commands for breakpoint(s) 1, one per line.
End with a line saying just "end".
>call rb_backtrace()
>continue
>end
(gdb) c
Continuing.

gdbunicorn にアタッチして

  • BF_crypt で 停止する
  • call rb_backtrace() でバックトレースを stderr に出力する
  • gdb を 再開する

という command をセットした。 ブレークポイントで停止してバックトレースを出して自動で再開することで、停止時間を極力短くすることができる。

one more

更に自動化、手順をファイルに書き出して stdin から読み込ませて手作業を減らした

break BF_crypt
command 1
  call rb_backtrace()
  continue
end
continue

こんな感じで扱える

sudo gdb -p <unicorn worker の pid>  < gdb-BF_crypt-of-unicorn

( これを実行すると unicorn worker プロセスが生きている限りバックトレースの採取が続いてしまう。「 n回 command を実行したら quit する」を実現するにはどうしたらよいのだろう? )

実行

gdb でアタッチして unicorn のログを tail していると、下記のようなバックトレースがバンバン採取できた

 from /path/to/current/vendor/bundle/ruby/2.3.0/bin/unicorn:23:in `<main>'
    from /path/to/current/vendor/bundle/ruby/2.3.0/bin/unicorn:23:in `load'
    from /path/to/current/vendor/bundle/ruby/2.3.0/gems/unicorn-5.2.0/bin/unicorn:126:in `<top (required)>'
略 ... 
    from /path/to/releases/2016120******/app/controllers/concerns/foo.rb:32:in `block in bar' 
    from /path/to/releases/2016120******/vendor/bundle/ruby/2.3.0/gems/devise-4.2.0/lib/devise/models/database_authenticatable.rb:45:in `valid_password?'
    from /path/to/releases/2016120******/vendor/bundle/ruby/2.3.0/gems/devise-4.2.0/lib/devise/encryptor.rb:18:in `compare'
    from /path/to/current/vendor/bundle/ruby/2.3.0/gems/bcrypt-3.1.11/lib/bcrypt/engine.rb:51:in `hash_secret'
    from /path/to/current/vendor/bundle/ruby/2.3.0/gems/bcrypt-3.1.11/lib/bcrypt/engine.rb:51:in `__bc_crypt'

(  大量のバックトレースがでてくるので、一部だけ )

採取できたバックトレースを比較してみて、とある concerrs 経由での呼び出しなのを特定できた。

アプリケーションをよく見知った人であれば Rails, BCrypt から devise の存在を連想してどこが怪しいかをポイントすることも可能だろう ( 実際にそういうレビューをもらえた 😊 )。デバッグツールによって推測を実証にできた。

rb_backtrace について

ruby のソース vm_backtrace.c を除くと下記のようなコードだった

void
rb_backtrace(void)
{
    vm_backtrace_print(stderr);
}

vm_backtrace_print() は下記の通り

static void
vm_backtrace_print(FILE *fp)
{   
    struct oldbt_arg arg;
    
    arg.func = oldbt_print;
    arg.data = (void *)fp;
    backtrace_each(GET_THREAD(),
                   oldbt_init,
                   oldbt_iter_iseq,
                   oldbt_iter_cfunc,
                   &arg);
}   

で、vm_backtrace.c を覗いていると rb_backtrace_print_as_bugreport() というのを見つけた

void
rb_backtrace_print_as_bugreport(void)
{   
    struct oldbt_arg arg;
    int i = 0;
    
    arg.func = oldbt_bugreport;
    arg.data = (int *)&i;

    backtrace_each(GET_THREAD(),
                   oldbt_init,
                   oldbt_iter_iseq,
                   oldbt_iter_cfunc,
                   &arg);
}

rb_backtrace_print_as_bugreport() を使ってみたらバックトレースのフォーマットが変わったのだった

-- Ruby level backtrace information ----------------------------------------
/path/to/current/vendor/bundle/ruby/2.3.0/bin/unicorn:23:in `<main>'
/path/to/current/vendor/bundle/ruby/2.3.0/bin/unicorn:23:in `load'
/path/to/current/vendor/bundle/ruby/2.3.0/gems/unicorn-5.2.0/bin/unicorn:126:in `<top (required)>'
/path/to/releases/20161208******/vendor/bundle/ruby/2.3.0/gems/unicorn-5.2.0/lib/unicorn/http_server.rb:132:in `start'

...

/path/to/20161208******/app/controllers/concerns/api/foo.rb:32:in `block in bar'
/path/to/20161208******/vendor/bundle/ruby/2.3.0/gems/devise-4.2.0/lib/devise/models/database_authenticatable.rb:45:in `valid_password?'
/path/toreleases/20161208******/vendor/bundle/ruby/2.3.0/gems/devise-4.2.0/lib/devise/encryptor.rb:18:in `compare'
/path/to/current/vendor/bundle/ruby/2.3.0/gems/bcrypt-3.1.11/lib/bcrypt/engine.rb:51:in `hash_secret'
/path/to/current/vendor/bundle/ruby/2.3.0/gems/bcrypt-3.1.11/lib/bcrypt/engine.rb:51:in `__bc_crypt'

右側の空白のオフセットが消えてログの最初にヘッダが一行入っていいるので、tail で追う際に見やすい。こっちでも問題ないだろうか

トレーニングライド

寒くなって朝の お布団峠 を越えられない

夜に1時間ほど走って終わり

練馬〜和光市〜朝霞 を往復するのがトレーニングコース。志木まで足を伸ばすこともある。陸上自衛隊朝霞駐屯地の前に 1.5 km ほどのストレート区間があり、路側帯も十分に広いので負荷をかけて走るのにちょうどよい (夜間は真っ暗な道のでつよいライトで照らそうね 🔦)

全体的にアップダウンはあまりないコース。荒川にかけて坂になってはいるが 高低差が小さいので物足りない。多摩丘陵のように緩急ついてると楽しいんだけどなぁ

公園で休憩していたら流れ星が見えた 冬本番

Google Play Music

Subsonic から Google Play Music に移行する - @banyan's blog を読んで、そういうやそんなのあったなと、 Google Play Music の存在を思い出して、家の外付けHDDで塩漬けになっていた iTunes の楽曲をアップロード祭りしている

f:id:hiboma:20161207152524p:plain

以前はアップロードの上限が2万曲だったはずで、iTunes にインポート済みの楽曲数だけで上限を超えてしまっていた。ローカルと Google Play Music の同期が中途半端になるのかな〜と思い利用していなかったのだが、上限が緩和されて5万曲になっていたのだね

f:id:hiboma:20161207153154p:plain

押し入れにしまい込んでいたインポートしていない CD の山も片付けられそうな気がする。あと 1000枚位あるので来年までかかりそうな気配

f:id:hiboma:20161207172443p:plain

アルバムの再生時に勝手に背景写真が付くけど、音源の発表と年代が近い写真が選択される仕組みがあってもいいんじゃないかな ... と思ったワンショット 😂 (メンバーも違うしね)


はせこさん、参考になりました。ありがとう 😊

奥多摩・風張峠ライド

12/3 奥多摩から風張峠をのぼってきた

続きを読む

ソースコードリーディング: KVM_RUN

おそらく KVM API の中で一番利用頻度の高い API で、複雑なAPI である。ユーザランドのスレッドが ioctl(2) + KVM_RUN を呼び出して、ゲストに移るまでを追っている

github.com

( ソースを追うだけで精一杯で、解説のようなことはできていないのでご了承を )

Intel VT-x の仕様が絡んでくる API で、詳細を含めた全貌把握は大変。ホストとゲスト間の遷移だけにフォーカスする

  • VMX non-root operation
  • VMX root operation
  • VMCS の Host State, Guest State、その他あれこれ
  • VMXON, VMLAUNCE, VMRESUME
  • VM entry , VM exit

... あたりのキーワードを syuu1228 さんのハイパーバイザの作り方Intel のマニュアル 等々で整理しつつ読み進めた

レジスタの扱いやハードウェア仮想化周りが難しいな

KVM_RUN を strace

qemu-kvm を strace すると ioctl(2) を捉えることができる

$ sudo ./strace -p $(  qemu-kvm の PID )  -f 

...

[pid 26557] <... ioctl resumed> , 0)    = 0
[pid 26557] ioctl(15, KVM_RUN, 0)       = 0
[pid 26579] <... ioctl resumed> , 0)    = 0
[pid 26557] ioctl(15, KVM_RUN <unfinished ...>
[pid 26574] <... ioctl resumed> , 0)    = 0
[pid 26579] ioctl(35, KVM_RUN <unfinished ...>
[pid 26574] ioctl(31, KVM_RUN <unfinished ...>
[pid 26579] <... ioctl resumed> , 0)    = 0
[pid 26579] ioctl(35, KVM_RUN, 0)       = 0
[pid 26579] ioctl(35, KVM_RUN, 0)       = 0
[pid 26579] ioctl(35, KVM_RUN, 0)       = 0
[pid 26579] ioctl(35, KVM_RUN, 0)       = 0
[pid 26579] ioctl(35, KVM_RUN, 0)       = 0
[pid 26579] ioctl(35, KVM_RUN <unfinished ...>
[pid 26574] <... ioctl resumed> , 0)    = 0
[pid 26557] <... ioctl resumed> , 0)    = 0
[pid 26574] ioctl(31, KVM_RUN <unfinished ...>
[pid 26557] ioctl(15, KVM_RUN <unfinished ...>
[pid 26574] <... ioctl resumed> , 0)    = 0
[pid 26557] <... ioctl resumed> , 0)    = 0
[pid 26574] ioctl(31, KVM_RUN <unfinished ...>

...

# 注: strace が古いと `KVM_FOO_BAR` のシンボルが逆引きされずに 16進数表記 = 0xae80 になる

ioctl(2) に渡しているデスクリプタは anon_inode:kvm-vcpu である。lsof でも確認できる

sudo ls -hal /proc/26520/fd
合計 0
dr-x------ 2 qemu qemu  0 12月  2 11:46 2016 .
dr-xr-xr-x 7 qemu qemu  0 11月 29 10:03 2016 ..
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 0 -> /dev/null
l-wx------ 1 qemu qemu 64 12月  2 11:46 2016 1 -> /var/log/libvirt/qemu/******.log
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 10 -> anon_inode:[signalfd]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 11 -> /var/lib/libvirt/images/******-1359447098.87
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 12 -> /var/lib/libvirt/images/******-1371804908.61
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 13 -> /var/lib/libvirt/images/******-1477466023.96
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 14 -> /var/lib/libvirt/images/******-1477468895.71
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 15 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 16 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 17 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 18 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 19 -> anon_inode:kvm-vcpu
l-wx------ 1 qemu qemu 64 12月  2 11:46 2016 2 -> /var/log/libvirt/qemu/******.log
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 20 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 21 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 22 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 23 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 24 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 25 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 26 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 263 -> /dev/net/tun
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 264 -> /dev/net/tun
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 27 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 28 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 29 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 3 -> socket:[372948322]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 30 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 31 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 32 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 33 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 34 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 35 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 36 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 37 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 38 -> anon_inode:kvm-vcpu
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 39 -> socket:[372948333]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 4 -> /dev/ptmx
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 40 -> anon_inode:[eventfd]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 41 -> anon_inode:[eventfd]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 42 -> anon_inode:[signalfd]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 43 -> socket:[372948334]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 44 -> anon_inode:[eventfd]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 45 -> anon_inode:[eventfd]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 46 -> anon_inode:[eventfd]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 47 -> anon_inode:[eventfd]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 5 -> /dev/kvm
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 6 -> anon_inode:kvm-vm
lr-x------ 1 qemu qemu 64 12月  2 11:46 2016 7 -> pipe:[372948328]
l-wx------ 1 qemu qemu 64 12月  2 11:46 2016 8 -> pipe:[372948328]
lrwx------ 1 qemu qemu 64 12月  2 11:46 2016 9 -> /var/lib/libvirt/images/******-disk0

社内の暇している KVM サーバ 上で動かしている 24 vCPU の VM 。 anon_inode:kvm-vcpu がたくさん生えている 😄

anon_inode は過去エントリでとりあげた

hiboma.hatenadiary.jp

CentOS7 1611 CR リポジトリを使う

アナウンスから少し時間が経ったが、 CentOS7 1611 ( RHEL 7.3 ベース ) の RPMCR リポジトリ で公開されている

AdditionalResources/Repositories/CR - CentOS Wiki に書いてある手順で CR リポジトリを使えるようになる

$ sudo yum update
$ sudo yum-config-manager --enable cr 
読み込んだプラグイン:fastestmirror
==================================================================================================== repo: cr =====================================================================================================
[cr]
async = True
bandwidth = 0
base_persistdir = /var/lib/yum/repos/x86_64/7
baseurl = http://mirror.centos.org/centos/7/cr/x86_64/
cache = 0
cachedir = /var/cache/yum/x86_64/7/cr
check_config_file_age = True
compare_providers_priority = 80

.... 省略

おもむろに全部 update するならえいやっと

$ sudo yum update

各種パッケージのバージョンを上げてあれこれ試せる。機能追加やバグっていた不具合なんかが修正されているかもしれない。とりあえずはカーネルのバージョンをあげただけで満足しいている 🍵

[vagrant@localhost ~]$ uname -a
Linux localhost.localdomain 3.10.0-514.el7.x86_64 #1 SMP Tue Nov 22 16:42:41 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

CR リポジトリについて詳しいことは あらためてを参照されたし

AdditionalResources/Repositories/CR - CentOS Wiki

正式リリースはいつだろう?

CentOS - Wikipedia で過去のリリース日を見ると、新しいバージョンの RHEL がでて1ヶ月も経てば CentOS のリリースも追随している。RHEL 7.3 が出たのが 2016/11/3 なので 12月初週にはリリースされるだろうか。

もうちょっと早く書けばよかった