kern.log-mds
kern.log-mds-Aug30
kern.log-oss
kern.log-oss-Aug30
[LU-2289] still haven't managed to acquire quota space from the quota master after 10 retries (err=0, rc=0) Created: 06/Nov/12 Updated: 29/Sep/15 Resolved: 29/Sep/15 |
|
| Status: | Resolved |
| Project: | Lustre |
| Component/s: | None |
| Affects Version/s: | Lustre 1.8.8 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Minor |
| Reporter: | Oz Rentas | Assignee: | Niu Yawei (Inactive) |
| Resolution: | Not a Bug | Votes: | 0 |
| Labels: | ptr | ||
| Environment: |
Lustre 1.8.8 + |
||
| Attachments: |
kern.log-mds
kern.log-mds-Aug30
kern.log-oss
kern.log-oss-Aug30
|
| Severity: | 3 |
| Rank (Obsolete): | 5479 |
| Description |
|
Even after adding the patch from At this site, we haven't added any other patches to 1.8.8. What do these messages mean? Is it possible that some of the other patches (like The customer hasn't noticed any functional issues, but of course that doesn't mean there aren't any. Quotas >4TB work on this system. |
| Comments |
| Comment by Peter Jones [ 06/Nov/12 ] |
|
Niu Could you please look into this one? Thanks Peter |
| Comment by Niu Yawei (Inactive) [ 06/Nov/12 ] |
|
I see lots of following errors in mds log: Jul 12 20:34:19 lfs-mds-2-1 kernel: Lustre: 7972:0:(lproc_quota.c:453:lprocfs_quota_wr_type()) lfs2-MDT0000: quotaon failed because quota files don't exist, please run quotacheck firstly Seems there is something wrong on MDT, so that quota was not turned on for MDT, but it's turned on for OST, so OST can't acquire quota from MDT and report the messages "still haven't managed to acquire quota space from the quota master after 10 retries". Could you check what's the quota configuration was used? (ug3 for both MDT & OST?) If rerun "lfs quotacheck" can fix your problem? I not, I think we'd collect debuglog for quotacheck to see why the amdin or local quota file wasn't created. Thanks. |
| Comment by Kit Westneat (Inactive) [ 07/Nov/12 ] |
|
Hi Niu, Sorry I didn't truncate the logs to the relevant dates, those are actually old messages. I will reupload the logs with only the relevant parts. In preparing these logs, I noticed that when the OSS was displaying the message, the MDT was having problems connecting: This actually looks like: I will try to get more information from the customer about when they are seeing the message and if they are running with the workaround suggested in Thanks, |
| Comment by Kit Westneat (Inactive) [ 07/Nov/12 ] |
|
logs only for Aug 30 |
| Comment by Niu Yawei (Inactive) [ 07/Nov/12 ] |
|
Thank you, Kit. Yes, the new log shows quite a lot of connection errors, I'm not sure if the filesystem was healty at that time. The most possible reason of OST constantly showing "still haven't managed to acquire quota space from the quota master after 10 retries (err=0, rc=0)" is that there are some kind of inconsistency between master (MDT) and slave (OST):
If the quota is supposed to be disabled, but writting files can cause the "still haven't...(err=0, rc=0)" message on OSS, you can rerun "lfs quotaoff" when all OSTs are up to make sure quota is disabled on each OST; That's what I can think of so far. |
| Comment by Kit Westneat (Inactive) [ 05/Dec/12 ] |
|
We've seen this issue again without any network issues. Is there any way to debug what is going on? The error only appears intermittently, so I think it's probably some kind of sync issue. Is there a way to tell what uid/gid is causing problems, or is it better to just redo the lfs quotacheck? |
| Comment by Kit Westneat (Inactive) [ 12/Mar/13 ] |
|
Hi Niu, The customer ran lfs quotaoff, quotaon, and quotacheck. The problem reappeared fairly quickly on one filesystem, and after a few weeks to the other filesystem. The customer asks: I noticed that the quota debug level prints information about the UID/GID that is causing problems. I will try to get quota debug logs during the event. Is there anything else we can get, or any other ideas? Thanks, |
| Comment by Niu Yawei (Inactive) [ 12/Mar/13 ] |
|
If the quota acquire constantly fail like this, the io will not finished. Could you run "lfs quota -v uid/gid" to see what's the quota limits of the uid/gid which is causing the problem? Thanks. |
| Comment by Kit Westneat (Inactive) [ 01/Apr/13 ] |
|
Hi Niu, I was able to run with quota debug enabled. The debug logs are very large, but I think we were able to see which groups were having the logs messages printed. There doesn't appear to be anything strange about them: Disk quotas for group hfip-gfdl (gid 19103): Would it be possible to see whether or not the quota space was eventually acquired? Do you think I would be able to trace it by pid? Or do different threads operate on the same quota task? Is there a transaction ID or anything? I'll look at the code too to see if I can tell. Also I could make the logs available. They are each about ~300MB compressed, ~11GB uncompressed. Thanks |
| Comment by Kit Westneat (Inactive) [ 01/Apr/13 ] |
|
Here are the quotas with -v: [root@Jet:fe6 ~]# lfs quota -v -g hfipprd /lfs1 [root@Jet:fe6 ~]# lfs quota -v -g hfip-gfdl /lfs1
[root@Jet:fe6 ~]# lfs quota -v -g rthfip-gfdl /lfs1 |
| Comment by Niu Yawei (Inactive) [ 02/Apr/13 ] |
|
Hi, Kit If you have debug log, you can see if the quota is acquired eventually by checking the pid. (find the pid in the message of "still haven't managed ...", and check if this thread is constantly printing such message or it moves on eventually). When you attach the log, I suggest you truncate out the useful part, otherwise, it could be too large. The useful part should be the messages nearby "still haven't managed ..." OST and the corresponding messages on MDS. I didn't find anything abnormal in the output of "lfs quota -u -v", thank you for providing this. |
| Comment by Kit Westneat (Inactive) [ 03/Apr/13 ] |
|
Hi Niu, I've uploaded the logs here: It's about a 3 second window on each server, but it's still about 20GB uncompressed. It looks like for the message at 1364224183, it tries 19 times before it finally acquires it. Is there anything in the MDT logs that would indicate why it took so long? I didn't see anything in particular, but it's tough to read. |
| Comment by Niu Yawei (Inactive) [ 07/Apr/13 ] |
|
Thank you, Kit. I checked the OSS log: 00040000:00000400:6:1364224183.636169:0:1558:0:(quota_interface.c:475:quota_chk_acq_common()) still haven't managed to acquire quota space from the quota master after 10 retries (err=0, rc=0) 00040000:04000000:6:1364224183.636179:0:1558:0:(quota_interface.c:482:quota_chk_acq_common()) recheck quota with rc: 0, cycle: 10 00040000:04000000:6:1364224183.636181:0:1558:0:(quota_adjust_qunit.c:172:quota_search_lqs()) lqs(ffff810846b6a280) id(19302) flag(2147483649) type(g) bunit(1048576) btune(524288) iunit(5120) itune(2560) lqs_bwrite_pending(6340608) lqs_iwrite_pending(0) ino_rec(0) blk_rec(2097152)refcount(11): search lqs 00040000:04000000:6:1364224183.636190:0:1558:0:(quota_interface.c:345:quota_check_common()) count=256 lqs_pending=6340608 qd_count=5087232 isblk=2 mb=0 pending[1]=1056768 00040000:04000000:6:1364224183.636193:0:1558:0:(quota_adjust_qunit.c:172:quota_search_lqs()) lqs(ffff810846b6a280) id(19302) flag(2147483649) type(g) bunit(1048576) btune(524288) iunit(5120) itune(2560) lqs_bwrite_pending(6340608) lqs_iwrite_pending(0) ino_rec(0) blk_rec(2097152)refcount(11): search lqs 00002000:04000000:6:1364224183.636199:0:1558:0:(fsfilt-ldiskfs.c:1601:fsfilt_ldiskfs_quotactl()) quotactl command 0x800007, id 10311, type 0 failed: -3 00040000:04000000:6:1364224183.636205:0:1558:0:(quota_adjust_qunit.c:172:quota_search_lqs()) lqs(ffff810846b6a280) id(19302) flag(2147483649) type(g) bunit(1048576) btune(524288) iunit(5120) itune(2560) lqs_bwrite_pending(6340608) lqs_iwrite_pending(0) ino_rec(0) blk_rec(2097152)refcount(11): search lqs 00040000:04000000:6:1364224183.636209:0:1558:0:(quota_context.c:347:check_cur_qunit()) type: b, limit: 50417631232, usage: 50416787456, pending_write: 6340608, record: 2097152, qunit_sz: 1048576, tune_sz: 524288, ret: 0. 00040000:04000000:6:1364224183.636214:0:1558:0:(quota_interface.c:482:quota_chk_acq_common()) recheck quota with rc: 0, cycle: 11 00040000:04000000:6:1364224183.636217:0:1558:0:(quota_adjust_qunit.c:172:quota_search_lqs()) lqs(ffff810846b6a280) id(19302) flag(2147483649) type(g) bunit(1048576) btune(524288) iunit(5120) itune(2560) lqs_bwrite_pending(6340608) lqs_iwrite_pending(0) ino_rec(0) blk_rec(2097152)refcount(11): search lqs 00040000:04000000:6:1364224183.636224:0:1558:0:(quota_interface.c:345:quota_check_common()) count=256 lqs_pending=6340608 qd_count=5087232 isblk=2 mb=0 pending[1]=1056768 00040000:04000000:6:1364224183.636227:0:1558:0:(quota_adjust_qunit.c:172:quota_search_lqs()) lqs(ffff810846b6a280) id(19302) flag(2147483649) type(g) bunit(1048576) btune(524288) iunit(5120) itune(2560) lqs_bwrite_pending(6340608) lqs_iwrite_pending(0) ino_rec(0) blk_rec(2097152)refcount(11): search lqs 00002000:04000000:6:1364224183.636231:0:1558:0:(fsfilt-ldiskfs.c:1601:fsfilt_ldiskfs_quotactl()) quotactl command 0x800007, id 10311, type 0 failed: -3 00040000:04000000:6:1364224183.636239:0:1558:0:(quota_adjust_qunit.c:172:quota_search_lqs()) lqs(ffff810846b6a280) id(19302) flag(2147483649) type(g) bunit(1048576) btune(524288) iunit(5120) itune(2560) lqs_bwrite_pending(6340608) lqs_iwrite_pending(0) ino_rec(0) blk_rec(2097152)refcount(11): search lqs 00040000:04000000:6:1364224183.636243:0:1558:0:(quota_context.c:347:check_cur_qunit()) type: b, limit: 50417631232, usage: 50416787456, pending_write: 6340608, record: 2097152, qunit_sz: 1048576, tune_sz: 524288, ret: 0. Looks there is pending acquire request (record: 2097152), and local limit will be able to satisfy current write request when the pending acquire done, so OST should wait for the pending reqeust, but it actually didn't wait, so quota_chk_acq_common() recycled many times until the pending request done. I didn't see why OST didn't wait on pending acquire so far, maybe there is something wrong with the lqs_blk_rec calculation? I'll look into it further. |
| Comment by Niu Yawei (Inactive) [ 08/Apr/13 ] |
|
Now I think it isn't a problem after I checked the large log for all processes (the small one I checked before is only for single process). When some uid/gid is approaching quota limit, the qunit size will be shrinked to the minimal size (1MB), and each quota acquire can only acquire 1MB limit, if there are many OST threads writing to the same uid/gid at this time, the acquired limit will be consumed very soon, so some writing threads have to recycle several times in the quota_chk_acq_common() until get required quota limit or fail with -EDQUOT at the end. |
| Comment by Kit Westneat (Inactive) [ 17/May/13 ] |
|
Is it possible that this could cause performance issues when the UID/GID is approaching the quota limit? Do you know if there have ever been performance tests run for this case? Thanks. |
| Comment by Niu Yawei (Inactive) [ 20/May/13 ] |
|
Yes, when approaching limit, write performance will be lower because quota unit is very small when approaching limit, and there will be much more quota acquire/release operations between ost & mdt, even worse, the write operation has to be blocked on the quota acquire operation sometimes. We didn't measure the performance in such unusual case. |
| Comment by Andreas Dilger [ 29/Sep/15 ] |
|
Closing old bug. |