title: correct use of linux inotify - reopen every time?
body: <p>I'm debugging a system load problem that a customer encounters on their production system and they've made a test application that simulates the load to reproduce the problem:</p>
  
  <p><img src="https://i.stack.imgur.com/VVr6U.png" alt="sexy graph"></p>
  
  <p>In this particular workload, one of the things the coder did was to:</p>
  
  <pre><code>while(1)
    initialize inotify
    watch a directory for events
    receive event
    process event
    remove watch
    close inotify fd
  </code></pre>
  
  <p>Strangely enough, the high system load comes from the <code>close()</code> of the inotify fd:</p>
  
  <pre><code>inotify_init()                          = 4 &lt;0.000020&gt;
  inotify_add_watch(4, "/mnt/tmp/msys_sim/QUEUES/Child_032", IN_CREATE) = 1 &lt;0.059537&gt;
  write(1, "Child [032] sleeping\n", 21)  = 21 &lt;0.000012&gt;
  read(4, "\1\0\0\0\0\1\0\0\0\0\0\0\20\0\0\0SrcFile.b8tlfT\0\0", 512) = 32 &lt;0.231012&gt;
  inotify_rm_watch(4, 1)                  = 0 &lt;0.000044&gt;
  close(4)                                = 0 &lt;0.702530&gt;
  open("/mnt/tmp/msys_sim/QUEUES/Child_032", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4 &lt;0.000031&gt;
  lseek(4, 0, SEEK_SET)                   = 0 &lt;0.000010&gt;
  getdents(4, /* 3 entries */, 32768)     = 88 &lt;0.000048&gt;
  getdents(4, /* 0 entries */, 32768)     = 0 &lt;0.000009&gt;
  write(1, "Child [032] dequeue [SrcFile.b8t"..., 37) = 37 &lt;0.000011&gt;
  unlink("/mnt/tmp/msys_sim/QUEUES/Child_032/SrcFile.b8tlfT") = 0 &lt;0.059298&gt;
  lseek(4, 0, SEEK_SET)                   = 0 &lt;0.000011&gt;
  getdents(4, /* 2 entries */, 32768)     = 48 &lt;0.000038&gt;
  getdents(4, /* 0 entries */, 32768)     = 0 &lt;0.000009&gt;
  close(4)                                = 0 &lt;0.000012&gt;
  inotify_init()                          = 4 &lt;0.000020&gt;
  inotify_add_watch(4, "/mnt/tmp/msys_sim/QUEUES/Child_032", IN_CREATE) = 1 &lt;0.040385&gt;
  write(1, "Child [032] sleeping\n", 21)  = 21 &lt;0.000903&gt;
  read(4, "\1\0\0\0\0\1\0\0\0\0\0\0\20\0\0\0SrcFile.mQgUSh\0\0", 512) = 32 &lt;0.023423&gt;
  inotify_rm_watch(4, 1)                  = 0 &lt;0.000012&gt;
  close(4)                                = 0 &lt;0.528736&gt;
  </code></pre>
  
  <p>What could possibly be causing the close() call to take such an enormous amount of time? I can identify two possible things:</p>
  
  <ul>
  <li>closing and reinitializing inotify <em>every</em> time</li>
  <li>There are 256K files (flat) in <code>/mnt/tmp/msys_sim/SOURCES</code> and a particular file in <code>/mnt/tmp/msys_sim/QUEUES/Child_032</code> is hardlinked to one in that directory. But SOURCES is never opened by the above process</li>
  </ul>
  
  <p>Is it an artifact of using inotify wrong? What can I point at to say "What you're doing is WRONG!"?</p>
  
  <hr>
  
  <p>Output of <code>perf top</code> (I had been looking for this!)</p>
  
  <pre><code>Events: 109K cycles
   70.01%  [kernel]      [k] _spin_lock
   24.30%  [kernel]      [k] __fsnotify_update_child_dentry_flags
    2.24%  [kernel]      [k] _spin_unlock_irqrestore
    0.64%  [kernel]      [k] __do_softirq
    0.60%  [kernel]      [k] __rcu_process_callbacks
    0.46%  [kernel]      [k] run_timer_softirq
    0.40%  [kernel]      [k] rcu_process_gp_end
  </code></pre>
  
  <p>Sweet! I suspect a spinlock somewhere and the <em>entire system</em> goes highly latent when this happens.</p>