As a background, I have been setting up database platforms since the 80s. So, in the past, I ran into a lot of problems with asynchronous I / O. This new and strange.
Firstly, I am using Oracle 12c with ASM on RHEL 7.1 64-bit (3.10.0-229). I used two EMC CX4-960 arrays with a total of 72 SSDs. I am doing a total of ~ 105K reads / s, 65K writes / sec. (Yes, this is a pretty tough storage!) The write delay to the disk is 2-3 ms. When oracle dbwriters clear the buffers (usually in large batches and asynchronous), the following strace snippet shows the completion of io_submit () and io_getevents () in a couple of milliseconds, then it takes a few milliseconds to complete all the records, and we move on to the next batch. (I got rid of the details of the presented blocks in the io_submit () lines:
294692 12:46:10.173955 io_submit(140662136606720, 301, ) = 301 <0.002482>
294692 12:46:10.178452 io_getevents(140662136606720, 38, 128, , {600, 0}) = 60 <0.000026>
294692 12:46:10.178766 times(NULL) = 439014359 <0.000016>
294692 12:46:10.178845 io_getevents(140662136606720, 128, 128, , {0, 0}) = 85 <0.000109>
294692 12:46:10.179352 io_getevents(140662136606720, 128, 128, , {0, 0}) = 62 <0.000118>
294692 12:46:10.180207 io_getevents(140662136606720, 94, 128, , {0, 0}) = 76 <0.000115>
294692 12:46:10.180743 io_getevents(140662136606720, 18, 128, , {0, 0}) = 16 <0.000122>
294692 12:46:10.181994 io_getevents(140662136606720, 2, 128, , {0, 0}) = 2 <0.000032>
294692 12:46:10.182393 times(NULL) = 439014359 <0.000016>
294692 12:46:10.182462 semtimedop(4718593, , 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.999632>
294692 12:46:13.182193 times(NULL) = 439014659 <0.000015>
294692 12:46:13.188183 io_submit(140662136606720, 319, ) = 319 <0.002741>
294692 12:46:13.193078 io_getevents(140662136606720, 40, 128, , {600, 0}) = 128 <0.000021>
294692 12:46:13.193583 times(NULL) = 439014660 <0.000018>
294692 12:46:13.193663 io_getevents(140662136606720, 128, 128, , {0, 0}) = 119 <0.000116>
294692 12:46:13.194364 io_getevents(140662136606720, 72, 128, , {0, 0}) = 59 <0.000123>
294692 12:46:13.195876 io_getevents(140662136606720, 13, 128, , {0, 0}) = 13 <0.000021>
294692 12:46:13.196650 times(NULL) = 439014661 <0.000017>
294692 12:46:13.196725 semtimedop(4718593, , 1, {2, 990000000}) = -1 EAGAIN (Resource temporarily unavailable) <2.989363>
294692 12:46:16.186196 times(NULL) = 439014960 <0.000015>
294692 12:46:16.194006 io_submit(140662136606720, 276, ) = 276 <0.002434>
294692 12:46:16.198285 io_getevents(140662136606720, 36, 128, , {600, 0}) = 42 <0.000017>
294692 12:46:16.198518 times(NULL) = 439014961 <0.000014>
294692 12:46:16.198572 io_getevents(140662136606720, 128, 128, , {0, 0}) = 48 <0.000092>
294692 12:46:16.198893 io_getevents(140662136606720, 128, 128, , {0, 0}) = 37 <0.000070>
. Tegile t3600, . IOPS . , Oracle " " 50% . Dbwriters , . , dbwriters . strace , . , iostat , 0,7 .
19131 18:35:06.903628 io_submit(140538814074880, 517, ) = 517 <0.505505>
19131 18:35:07.414281 io_getevents(140538814074880, 40, 128, , {600, 0}) = 128 <0.000014>
19131 18:35:07.415091 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 <0.000012>
19131 18:35:07.416139 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 <0.000010>
19131 18:35:07.417134 semctl(753668, 33, SETVAL, 0x1) = 0 <0.000017>
19131 18:35:07.417553 semctl(688130, 103, SETVAL, 0x1) = 0 <0.000014>
19131 18:35:07.417640 semctl(655361, 130, SETVAL, 0x1) = 0 <0.000013>
19131 18:35:07.419923 io_submit(140538814074880, 248, ) = 248 <0.250174>
19131 18:35:07.673864 io_getevents(140538814074880, 22, 128, , {600, 0}) = 128 <0.000019>
19131 18:35:07.674735 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 <0.000010>
19131 18:35:07.676021 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 <0.000020>
19131 18:35:07.676660 semctl(753668, 5, SETVAL, 0x1) = 0 <0.000021>
19131 18:35:07.680954 io_submit(140538814074880, 507, ) = 507 <0.503491>
19131 18:35:08.190096 io_getevents(140538814074880, 38, 128, , {600, 0}) = 128 <0.000010>
19131 18:35:08.190617 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 <0.000008>
19131 18:35:08.193571 io_getevents(140538814074880, 128, 128, , {0, 0}) = 128 <0.000025>
19131 18:35:08.196128 semctl(720899, 38, SETVAL, 0x1) = 0 <0.000026>
, - io_submit() 517 505 . ?
, ? , - . FWIW, . , -