> Hi David and Alexandre,
>
> Does this only happen with random writes or also sequential writes? If it
> happens with sequential writes as well, does it happen with rados bench?
>
> --
> Mark Nelson
> Performance Engineer
> Inktank
Hi Mark,
I have only ever seen it with random writes. I'll retry rados bench in a few minutes to double check - are there any other tests you would like me to run?
I'm currently waiting for some iozone tests to finish. When the sequential tests are running the logs are fine, as soon as the random writes start, the logs start to fill with messages like:
2012-07-05 19:10:00.599250 osd.6 10.0.1.42:6802/2145 1151 : [WRN] slow request 37.933071 seconds old, received at 2012-07-05 19:09:22.665917: osd_op(client.96416.0:91965 rb.0.1.00000000015f [write 4022272~4096] 2.3777e91a snapc 11=[11,10]) v4 currently waiting for sub ops
2012-07-05 19:10:00.599258 osd.6 10.0.1.42:6802/2145 1152 : [WRN] slow request 37.932836 seconds old, received at 2012-07-05 19:09:22.666152: osd_op(client.96416.0:91966 rb.0.1.00000000015f [write 4034560~4096] 2.3777e91a snapc 11=[11,10]) v4 currently waiting for sub ops
2012-07-05 19:10:03.278141 mon.0 10.0.1.40:6789/0 493 : [INF] pgmap v7564: 1344 pgs: 1344 active+clean; 5183 MB data, 11066 MB used, 1367 GB / 1377 GB avail
2012-07-05 19:09:55.388448 osd.3 10.0.1.41:6802/2540 160 : [WRN] 6 slow requests, 6 included below; oldest blocked for > 32.622016 secs
2012-07-05 19:09:55.388463 osd.3 10.0.1.41:6802/2540 161 : [WRN] slow request 32.622016 seconds old, received at 2012-07-05 19:09:22.766269: osd_op(client.96416.0:92308 rb.0.1.00000000017b [write 4001792~4096] 2.f606a6c6 snapc 11=[11,10]) v4 currently waiting for sub ops
��.n��������+%������w��{.n����z��u���ܨ}���Ơz�j:+v�����w����ޙ��&�)ߡ�a����z�ޗ���ݢj��w�f
