CentOS7.5 カーネルの fsnotiy のバグと libev の inotify_add_watch(2) と inotify_rm_watch(2) を調べたけどよくわからん

hiboma.hatenadiary.jp

というエントリを書いたのちに、下記のような感想を頂いていて

これ、そもそもin_tailプラグインがinotify_rm_watch→inotify_add_watchを繰り返してるのはなんでなんだろ？必要性がないような… / “CentOS7.5 の fsnotify がレースコンディ…” https://t.co/WHEMOZ4RUz

— Mitsuru SHIMAMURA (@smbd) June 12, 2018

確かにそうだなぁ〜〜 と思って td-agent -> libev のソースを追って見ました。

が、設計の意図は理解できず、特に収穫はなかった内容です 😯 せっかくなのでソースを突き止めたあたりのメモ等を残しておきます

環境

再現の環境は前回書いたエントリに倣う

hiboma.hatenadiary.jp

inotify_add_watch(2) と inotify_add_rm_watch(2) が呼びだされる場所を特定する

まずは問題となっているシステムコールがどういったパスで呼び出されるかを調べた. いろいろな方法があると思うが perf trace --call-graph dwarf で絞り込んだ.

-bash-4.2$ sudo perf trace -einotify_add_watch,inotify_rm_watch -p 1370 --call-graph dwarf
     0.000 ( 0.053 ms): ruby/1423 inotify_rm_watch(fd: 13<anon_inode:inotify>, wd: 1271                 ) = 0
                                       inotify_rm_watch (/usr/lib64/libc-2.17.so) 👈
                                       stat_timer_cb (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       infy_wd (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       infy_cb (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       ev_invoke_pending (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       ev_run (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       Coolio_Loop_run_once (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       vm_call_cfunc (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       vm_exec_core (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       vm_exec (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       vm_call0_body.constprop.64 (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       rb_vm_call (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       rb_method_call_with_block (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       bmcall (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       invoke_block_from_c (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       vm_invoke_proc (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       rb_vm_invoke_proc (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       thread_start_func_2 (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       thread_start_func_1 (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       start_thread (/usr/lib64/libpthread-2.17.so)
                                       __clone (/usr/lib64/libc-2.17.so)
     0.082 ( 0.012 ms): ruby/1423 inotify_add_watch(fd: 13<anon_inode:inotify>, pathname: 0x27a3bba0, mask: 570429382) = 1272
                                       inotify_add_watch (/usr/lib64/libc-2.17.so) 👈 
                                       infy_add (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so) 
                                       stat_timer_cb (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       infy_wd (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       infy_cb (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       ev_invoke_pending (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       ev_run (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       Coolio_Loop_run_once (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io_ext.so)
                                       vm_call_cfunc (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       vm_exec_core (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       vm_exec (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       vm_call0_body.constprop.64 (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       rb_vm_call (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       rb_method_call_with_block (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       bmcall (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       invoke_block_from_c (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       vm_invoke_proc (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       rb_vm_invoke_proc (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       thread_start_func_2 (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       thread_start_func_1 (/opt/td-agent/embedded/lib/libruby.so.2.1.0)
                                       start_thread (/usr/lib64/libpthread-2.17.so)

スーパー便利 (改行がはいってて少し見難いですね. sorry )

コールグラフを眺めることで stat_timer_cb の中で

• infy_del
• infy_add

を呼び出し、それぞれの内部で inotify_rm_watch(2) , inotify_add_watch(2) を呼び出すのがわかった

stat_timer_cb

ソースは以下を git clone

github.com

監視したいファイルの struct stat に変更があれば infy_del ( inotify_rm_watch ), infy_add ( inotify_add_watch ) するというのが読み取れる.

noinline
static void
stat_timer_cb (EV_P_ ev_timer *w_, int revents)
{
  ev_stat *w = (ev_stat *)(((char *)w_) - offsetof (ev_stat, timer));

  ev_statdata prev = w->attr;
  ev_stat_stat (EV_A_ w);

  /* memcmp doesn't work on netbsd, they.... do stuff to their struct stat */
  if (
    prev.st_dev      != w->attr.st_dev
    || prev.st_ino   != w->attr.st_ino
    || prev.st_mode  != w->attr.st_mode
    || prev.st_nlink != w->attr.st_nlink
    || prev.st_uid   != w->attr.st_uid
    || prev.st_gid   != w->attr.st_gid
    || prev.st_rdev  != w->attr.st_rdev
    || prev.st_size  != w->attr.st_size
    || prev.st_atime != w->attr.st_atime
    || prev.st_mtime != w->attr.st_mtime
    || prev.st_ctime != w->attr.st_ctime
  ) {
      /* we only update w->prev on actual differences */
      /* in case we test more often than invoke the callback, */
      /* to ensure that prev is always different to attr */
      w->prev = prev;

      #if EV_USE_INOTIFY
        if (fs_fd >= 0)
          {
            infy_del (EV_A_ w); 👈
            infy_add (EV_A_ w); 👈
            ev_stat_stat (EV_A_ w); /* avoid race... */
          }
      #endif

      ev_feed_event (EV_A_ w, EV_STAT);
    }
}

infy_add

inotify_add_watch(2) を呼び出す

noinline
static void
infy_add (EV_P_ ev_stat *w)
{
  w->wd = inotify_add_watch (fs_fd, w->path,
                             IN_ATTRIB | IN_DELETE_SELF | IN_MOVE_SELF | IN_MODIFY
                             | IN_CREATE | IN_DELETE | IN_MOVED_FROM | IN_MOVED_TO
                             | IN_DONT_FOLLOW | IN_MASK_ADD);

  if (w->wd >= 0)
    {
      struct statfs sfs;

      /* now local changes will be tracked by inotify, but remote changes won't */
      /* unless the filesystem is known to be local, we therefore still poll */
      /* also do poll on <2.6.25, but with normal frequency */

      if (!fs_2625)
        w->timer.repeat = w->interval ? w->interval : DEF_STAT_INTERVAL;
      else if (!statfs (w->path, &sfs)
               && (sfs.f_type == 0x1373 /* devfs */
                   || sfs.f_type == 0x4006 /* fat */
                   || sfs.f_type == 0x4d44 /* msdos */
                   || sfs.f_type == 0xEF53 /* ext2/3 */
                   || sfs.f_type == 0x72b6 /* jffs2 */
                   || sfs.f_type == 0x858458f6 /* ramfs */
                   || sfs.f_type == 0x5346544e /* ntfs */
                   || sfs.f_type == 0x3153464a /* jfs */
                   || sfs.f_type == 0x9123683e /* btrfs */
                   || sfs.f_type == 0x52654973 /* reiser3 */
                   || sfs.f_type == 0x01021994 /* tmpfs */
                   || sfs.f_type == 0x58465342 /* xfs */))
        w->timer.repeat = 0.; /* filesystem is local, kernel new enough */
      else
        w->timer.repeat = w->interval ? w->interval : NFS_STAT_INTERVAL; /* remote, use reduced frequency */
    }
  else
    {

... 略
      
    }

  if (w->wd >= 0)
    wlist_add (&fs_hash [w->wd & ((EV_INOTIFY_HASHSIZE) - 1)].head, (WL)w);

  /* now re-arm timer, if required */
  if (ev_is_active (&w->timer)) ev_ref (EV_A);
  ev_timer_again (EV_A_ &w->timer);
  if (ev_is_active (&w->timer)) ev_unref (EV_A);
}

infy_add

inotify_rm_watch(2) を呼び出す. エラーハンドリングをしていないな

noinline
static void
infy_del (EV_P_ ev_stat *w)
{
  int slot;
  int wd = w->wd;

  if (wd < 0)
    return;

  w->wd = -2;
  slot = wd & ((EV_INOTIFY_HASHSIZE) - 1);
  wlist_del (&fs_hash [slot].head, (WL)w);

  /* remove this watcher, if others are watching it, they will rearm */
  inotify_rm_watch (fs_fd, wd);
}

... と局所的にコードをみても inotify の扱いがどういう意図をもってなされているのかよくわからなかった.

ドキュメントを読む

周辺のコードを読むにつれて、上記に掲載したコードは libev で ev_stat(3) を読んだ際の下位の関数だと理解したのだが、ドキュメントで該当の項を読んでも inotify の扱いについてはヒントを得られなかった

pod.tst.eu

過去のコミットを読む

過去のコミットに遡ってみたが、git の最初期のコミットから変更は入ってないようだ. svn -> git に以降したようだけど、 http://rev.rubyforge.org/svn/trunk は無いし svn のコードはどこにあるのかな?

commit 3f5a4fe492580c1f3a87e01fbf87f558de4c470f
Author: tarcieri <tarcieri@ea6e6bc6-682b-4e20-bb59-304e6edd756d>
Date:   Tue Dec 18 06:57:26 2007 +0000

    Initial commit of codebase to trunk
    
    git-svn-id: http://rev.rubyforge.org/svn/trunk@2 ea6e6bc6-682b-4e20-bb59-304e6edd756d

# ... 略


+  ) {
+      #if EV_USE_INOTIFY
+        infy_del (EV_A_ w);
+        infy_add (EV_A_ w);
+        ev_stat_stat (EV_A_ w); /* avoid race... */
+      #endif
+
+      ev_feed_event (EV_A_ w, EV_STAT);
+    }
+}