title: io_submit waits for all oracle dbwriter I/Os
body: <p>By way of background, I have been tuning platforms for databases since the 80s. So, I have dealt with a lot of async I/O issues in the past. This one is new, and weird.</p>
  
  <p>First, the I am using Oracle 12c with ASM on RHEL 7.1 64-bit (3.10.0-229). I have been using two EMC CX4-960 arrays with a total of 72 SSDs. I am doing a total of ~105K reads/s, 65K writes/sec. (Yes, that's a pretty beefy storage backend!) The disk write latency is 2-3ms.  When the oracle dbwriters flush buffers (typically in large batches, and async), the following strace fragment shows io_submit() and io_getevents() complete in a couple of milliseconds, it then takes a few milliseconds for all the writes to complete and we move to the next batch. (I got rid of the details of the submitted blocks in the io_submit() lines:</p>
  
  <pre><code>294692 12:46:10.173955 io_submit(140662136606720, 301, ) = 301 &lt;0.002482&gt;
  294692 12:46:10.178452 io_getevents(140662136606720, 38, 128, , {600, 0}) = 60 &lt;0.000026&gt;
  294692 12:46:10.178766 times(NULL)      = 439014359 &lt;0.000016&gt;
  294692 12:46:10.178845 io_getevents(140662136606720, 128, 128, , {0, 0}) = 85 &lt;0.000109&gt;
  294692 12:46:10.179352 io_getevents(140662136606720, 128, 128, , {0, 0}) = 62 &lt;0.000118&gt;
  294692 12:46:10.180207 io_getevents(140662136606720, 94, 128, , {0, 0}) = 76 &lt;0.000115&gt;
  294692 12:46:10.180743 io_getevents(140662136606720, 18, 128, , {0, 0}) = 16 &lt;0.000122&gt;
  294692 12:46:10.181994 io_getevents(140662136606720, 2, 128, , {0, 0}) = 2 &lt;0.000032&gt;
  294692 12:46:10.182393 times(NULL)      = 439014359 &lt;0.000016&gt;
  294692 12:46:10.182462 semtimedop(4718593, , 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) &lt;2.999632&gt;
  294692 12:46:13.182193 times(NULL)      = 439014659 &lt;0.000015&gt;
  294692 12:46:13.188183 io_submit(140662136606720, 319, ) = 319 &lt;0.002741&gt;
  294692 12:46:13.193078 io_getevents(140662136606720, 40, 128, , {600, 0}) = 128 &lt;0.000021&gt;
  294692 12:46:13.193583 times(NULL)      = 439014660 &lt;0.000018&gt;
  294692 12:46:13.193663 io_getevents(140662136606720, 128, 128, , {0, 0}) = 119 &lt;0.000116&gt;
  294692 12:46:13.194364 io_getevents(140662136606720, 72, 128, , {0, 0}) = 59 &lt;0.000123&gt;
  294692 12:46:13.195876 io_getevents(140662136606720, 13, 128, , {0, 0}) = 13 &lt;0.000021&gt;
  294692 12:46:13.196650 times(NULL)      = 439014661 &lt;0.000017&gt;
  294692 12:46:13.196725 semtimedop(4718593, , 1, {2, 990000000}) = -1 EAGAIN (Resource temporarily unavailable) &lt;2.989363&gt;
  294692 12:46:16.186196 times(NULL)      = 439014960 &lt;0.000015&gt;
  294692 12:46:16.194006 io_submit(140662136606720, 276, ) = 276 &lt;0.002434&gt;
  294692 12:46:16.198285 io_getevents(140662136606720, 36, 128, , {600, 0}) = 42 &lt;0.000017&gt;
  294692 12:46:16.198518 times(NULL)      = 439014961 &lt;0.000014&gt;
  294692 12:46:16.198572 io_getevents(140662136606720, 128, 128, , {0, 0}) = 48 &lt;0.000092&gt;
  294692 12:46:16.198893 io_getevents(140662136606720, 128, 128, , {0, 0}) = 37 &lt;0.000070&gt;
  </code></pre>
  
  <p>So far, so good. I then switched to two Tegile t3600 arrays I am testing. These guys are even faster, and can give me more IOPS at lower latencies. The problem is that I quickly run into Oracle "free buffer waits" at 50% and higher. The dbwriters aren't able to keep up, forcing foreground writes and all kinds of bad things. It's a surprise that the dbwriters can't flush enough buffers with such fast storage. But strace shows why. Note that iostat shows the average disk write latency is right around 0.7ms.</p>
  
  <pre><code>19131 18:35:06.903628 io_submit(140538814074880, 517, ) = 517 &lt;0.505505&gt;
  19131 18:35:07.414281 io_getevents(140538814074880, 40, 128, , {600, 0}) = 128 &lt;0.000014&gt;
  19131 18:35:07.415091 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 &lt;0.000012&gt;
  19131 18:35:07.416139 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 &lt;0.000010&gt;
  19131 18:35:07.417134 semctl(753668, 33, SETVAL, 0x1) = 0 &lt;0.000017&gt;
  19131 18:35:07.417553 semctl(688130, 103, SETVAL, 0x1) = 0 &lt;0.000014&gt;
  19131 18:35:07.417640 semctl(655361, 130, SETVAL, 0x1) = 0 &lt;0.000013&gt;
  19131 18:35:07.419923 io_submit(140538814074880, 248, ) = 248 &lt;0.250174&gt;
  19131 18:35:07.673864 io_getevents(140538814074880, 22, 128, , {600, 0}) = 128 &lt;0.000019&gt;
  19131 18:35:07.674735 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 &lt;0.000010&gt;
  19131 18:35:07.676021 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 &lt;0.000020&gt;
  19131 18:35:07.676660 semctl(753668, 5, SETVAL, 0x1) = 0 &lt;0.000021&gt;
  19131 18:35:07.680954 io_submit(140538814074880, 507, ) = 507 &lt;0.503491&gt;
  19131 18:35:08.190096 io_getevents(140538814074880, 38, 128, , {600, 0}) = 128 &lt;0.000010&gt;
  19131 18:35:08.190617 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 &lt;0.000008&gt;
  19131 18:35:08.193571 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 &lt;0.000025&gt;
  19131 18:35:08.196128 semctl(720899, 38, SETVAL, 0x1) = 0 &lt;0.000026&gt;
  </code></pre>
  
  <p>So, for some reason, io_submit() with 517 blocks takes 505ms to return. Why?</p>
  
  <p>Any ideas why this might be happening?  It appears that the array is somehow telling the OS to issue the writes serially. FWIW, I have even enabled write-back caching of writes in the array controllers. So it appears to be something in the OS itself </p>