背景として、私は 80 年代からデータベースのプラットフォームをチューニングしてきました。そのため、私は過去に多くの非同期 I/O の問題に対処してきました。これは新しく、奇妙です。
まず、RHEL 7.1 64 ビット (3.10.0-229) で Oracle 12c と ASM を使用しています。合計 72 個の SSD を備えた 2 つの EMC CX4-960 アレイを使用しています。合計約 105K の読み取り/秒、65K の書き込み/秒を実行しています。(はい、かなり強力なストレージ バックエンドです!) ディスク書き込みレイテンシは 2 ~ 3 ミリ秒です。Oracle dbwriters がバッファーをフラッシュする場合 (通常は大きなバッチで非同期)、次の strace フラグメントは、io_submit() と io_getevents() が数ミリ秒で完了することを示しています。その後、すべての書き込みが完了するまでに数ミリ秒かかります。次のバッチへ。(提出されたブロックの詳細を io_submit() 行で削除しました:
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>
ここまでは順調ですね。次に、テスト中の 2 つの Tegile t3600 アレイに切り替えました。これらの人はさらに高速で、より低いレイテンシーでより多くの IOPS を提供できます。問題は、50% 以上で Oracle の「空きバッファ待機」にすぐに遭遇することです。dbwriter は追いつくことができず、フォアグラウンド書き込みやあらゆる種類の悪いことが強制されます。これほど高速なストレージでは、dbwriter が十分なバッファをフラッシュできないことは驚くべきことです。しかし、 strace はその理由を示しています。iostat は、平均ディスク書き込みレイテンシーが約 0.7ms であることを示していることに注意してください。
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>
そのため、何らかの理由で、517 ブロックの io_submit() が返されるまでに 505 ミリ秒かかります。なんで?
なぜこれが起こっているのでしょうか?アレイが何らかの方法で OS に書き込みを連続して発行するように指示しているようです。FWIW、アレイコントローラーで書き込みのライトバックキャッシュを有効にしました。したがって、OS自体に何かがあるようです