|
Niu
Could you please look at this one?
Thanks
Peter
|
|
Hi Chris,
Did you see any error message when short rw happened?
|
|
It is looking like all of the ones I have examined thus far are associated with evictions due to expired lock callback timers (expiration times vary from around 100s to over 4400s).
"slow" messages are pretty much constant on the servers when they are under load. Here are some samples:
2011-11-20 21:09:17 Lustre: 9536:0:(filter.c:3455:filter_setattr()) lc2-OST002f: slow i_alloc_sem 223s
2011-11-20 21:26:34 Lustre: 10785:0:(filter_io_26.c:775:filter_commitrw_write()) lc2-OST001f: slow direct_io 155s
2011-11-20 21:09:15 Lustre: 10883:0:(filter_io_26.c:701:filter_commitrw_write()) lc2-OST002f: slow quota init 248s
2011-11-20 21:27:19 Lustre: 10931:0:(lustre_fsfilt.h:332:fsfilt_setattr()) lc2-OST001f: slow setattr 155s
2011-11-20 21:28:38 Lustre: 9651:0:(filter.c:1447:filter_parent_lock()) lc2-OST0003: slow parent lock 263s
2011-11-20 21:28:38 Lustre: 10710:0:(filter.c:3253:filter_setattr_internal()) lc2-OST0003: slow i_alloc_sem and i_mutex 262s
2011-11-20 21:28:38 Lustre: 9651:0:(filter_io.c:431:filter_preprw_read()) lc2-OST0003: slow preprw_read setup 263s
2011-11-22 03:36:54 LustreError: 8522:0:(lustre_fsfilt.h:266:fsfilt_brw_start_log()) lc2-OST000f: slow journal start 427s
2011-11-22 03:36:54 LustreError: 8522:0:(filter_io_26.c:718:filter_commitrw_write()) lc2-OST000f: slow brw_start 427s
And it is not unusual for them to be stuck for 600+ seconds.
It looks like usually a "partial" read or write will be accompanied with an EIO at close() time. Sometimes occasionally a read or write will get the EIO.
|
|
Yes, it is looking like the short reads and writes are due to the evictions, so they are reasonable in that case. We could change this ticket's summary if you like.
|
|
Most of us are going to be gone for the holiday, so we'll investigate further on Monday. We'll need to figure out why we are seeing evictions more often with 2.1 than 1.8 with this workload.
|
|
It'll be great to collect the debug log on clients and MDS as well.
We do read/write stripe by stripe, so the short read/write should be multiple of 1MB on 1MB stripe size system.
|
|
There is a similar one at LU-874 and has log attached. Though the log was truncated, it told me a lot of things. I guess one of completion AST was dropped due to network problem. More log is needed to address it.
Chris, can you reproduce this problem constantly? If this is the case, please run it again with a larger debug memory, by DEBUG_SIZE=200 for example. It's unpractical to transfer 200MB log to maloo, so you may upload it to our ftp site.
|
|
I'm uploading two debug log files with +rpctrace dumped due to client eviction:
LU-874.lustre-log.client.1322741878.98479
LU-874.lustre-log.oss.1322741854.6037
One suspicious thing we noticed in the server log.
Client evicted when timer expires after 257s:
00010000:00020000:9.1:1322741808.246787:0:0:0:(ldlm_lockd.c:356:waiting_locks_callback()) ### lock callback timer expired after 257s: evicting client at 192.168.121.109@o2ib2 ns: filter-lc3-OST0003_UUID lock: ffff8802b94e5d80/0x36f903476b7f53b8 lrc: 3/0,0 mode: PW/PW res: 6806706/0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->1048575) flags: 0x20 remote: 0xa18374fc160b5b35 expref: 35 pid: 6063 timeout 4353798639
46 seconds later after the client has reconnected it is evicted again for timers expired after 303s. Shouldn't all callback timers for the client be cancelled when it was evicted the first time?
00010000:00020000:9.1:1322741854.246954:0:0:0:(ldlm_lockd.c:356:waiting_locks_callback()) ### lock callback timer expired after 303s: evicting client at 192.168.121.109@o2ib2 ns: filter-lc3-OST0003_UUID lock: ffff88028fb26480/0x36f903476b7f53fe lrc: 3/0,0 mode: PW/PW res: 6806684/0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->1048575) flags: 0x20 remote: 0xa18374fc160b5b58 expref: 34 pid: 6063 timeout 4353844679
00010000:00020000:9.1:1322741854.246985:0:0:0:(ldlm_lockd.c:356:waiting_locks_callback()) ### lock callback timer expired after 303s: evicting client at 192.168.121.109@o2ib2 ns: filter-lc3-OST0003_UUID lock: ffff8801850df240/0x36f903476b7f54d7 lrc: 3/0,0 mode: PW/PW res: 6806686/0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->1048575) flags: 0x20 remote: 0xa18374fc160b5b90 expref: 34 pid: 7641 timeout 4353844693
00010000:00020000:9.1:1322741854.246992:0:0:0:(ldlm_lockd.c:356:waiting_locks_callback()) ### lock callback timer expired after 303s: evicting client at 192.168.121.109@o2ib2 ns: filter-lc3-OST0003_UUID lock: ffff8804421d3480/0x36f903476b7f547c lrc: 3/0,0 mode: PW/PW res: 6806702/0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->1048575) flags: 0x20 remote: 0xa18374fc160b5b7b expref: 34 pid: 7860 timeout 4353844693
00010000:00020000:9.1:1322741854.246999:0:0:0:(ldlm_lockd.c:356:waiting_locks_callback()) ### lock callback timer expired after 303s: evicting client at 192.168.121.109@o2ib2 ns: filter-lc3-OST0003_UUID lock: ffff880170ca3480/0x36f903476b7f54de lrc: 3/0,0 mode: PW/PW res: 6806690/0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->1048575) flags: 0x20 remote: 0xa18374fc160b5b97 expref: 34 pid: 7641 timeout 4353844694
00010000:00020000:9.1:1322741854.247044:0:0:0:(ldlm_lockd.c:356:waiting_locks_callback()) ### lock callback timer expired after 303s: evicting client at 192.168.121.109@o2ib2 ns: filter-lc3-OST0003_UUID lock: ffff88022b0b76c0/0x36f903476b7f5604 lrc: 3/0,0 mode: PW/PW res: 6806704/0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->1048575) flags: 0x20 remote: 0xa18374fc160b5bdd expref: 34 pid: 7641 timeout 4353844904
|
|
Jinshan meant LU-873 I believe.
|
|
Chris, yes, it is. Thanks.
Ned: indeed, those locks should have been removed from waiting list during eviction. You can compress the log so that it's easier to upload.
|
|
The log didn't provide us enough information, unfortunately. The lock was about to cancel at 1322741541 (1322741808 - 267 = 1322741541), but nothing was printed during that time in client log. Can you please rerun the test with the following debug set:
[root@mercury tests]# lctl get_param debugdebug=
inode cache ha info warning nettrace page dlmtrace error emerg rpctrace vfstrace console
at the client side. And the on the ost side:
[root@mercury tests]# lctl set_param debug="cache ha info nettrace dlmtrace rpctrace"
debug=cache ha info nettrace dlmtrace rpctrace
Please also make sure enough memory is reserved by `lctl set_param debug_mb=200' for example.
|
|
BTW: the OSS log looks isn't uploaded?
|
|
The original ftp transfer reported success, but I've compressed and attached it here.
|
|
We had another occurence today with the requested debugging options enabled. Uploading client and oss logs to ftp.whamcloud.com/uploads:
LU-874.lustre-log.client.1322853642.73988.txt.gz
LU-874.lustre-log.oss.1322853642.5882.txt.gz
|
|
The server evicts the client at 192.168.121.146@o2ib2. But I can't see in the server's log any place that it ever sent the lock revocation. Am I missing something?
If the logs can be believed, it appears that the server is to blame for the eviction.
|
|
There were two eviction on the server side:
Unfortunately I didn't find any information about this lock prior than that time, even there was no IO to this object prior that time either. I was expecting something printed for adding this lock into waiting list. It looks like there were some log missed in the middle, I don't know why?
For the 2nd occurrence of eviction at the OST, I can find some information with the lock cookie:
From the above log, obviously the process 6243 is in the middle of canceling that lock(with cookie 0x14c71a0a40d66e1c), and the RPC x1386945716847253 was flushing the pages into OST0002, but for unknown reason that RPC never appeared at the OST.
I suspect the OST is in extremely busy at that time:
So I guess the root cause would be that the OSS was extremely busy serving IO requests so as to not get any chance to serve that write request.
However, before we dive into it, we should make sure that it's the real cause. So let's do the followings:
0. set big enough DEBUG_MB size at clients, 200MB for example;
1. apply the same debug policy as I mentioned above;
2. please monitor the OSS stats at: /proc/fs/lustre/ost/OSS/ost_io/stats on the OSS nodes.
Thanks.
|
|
BTW, did you see any abnormal dmesg on the client and server nodes?
|
From the above log, obviously the process 6243 is in the middle of canceling that lock(with cookie 0x14c71a0a40d66e1c), and the RPC x1386945716847253 was flushing the pages into OST0002, but for unknown reason that RPC never appeared at the OST.
Right, the process 6243 is in the middle of handling blocking ast, but RPC x1386945716847253 looks not the flush RPC (it's opcode is -1), and from the log:
00000008:00000040:4.0:1322853642.174480:0:6243:0:(osc_io.c:133:osc_io_submit()) 72 1
00000008:00000040:4.0:1322853642.174627:0:6243:0:(osc_io.c:227:osc_io_submit()) 72/0 0
00000008:00000040:4.0:1322853642.174873:0:6243:0:(osc_io.c:133:osc_io_submit()) 184 1
00000008:00000040:4.0:1322853642.174905:0:6243:0:(osc_io.c:227:osc_io_submit()) 184/0 0
we can see that client didn't trigger flush for this lock cancel (the pages might have been flushed already), and following logs
00010000:00010000:4.0:1322853642.175313:0:6243:0:(ldlm_request.c:1126:ldlm_cli_cancel_req()) skipping cancel on invalid import ffff880434578000
shows that the client import is already invalid before sending cancel RPC, so the cancel RPC isn't sent either.
I guess that the blocking ast handler on client took too much time, which caused the lock expired on server and the client was evicted. Unfortunately, the client log is too short (only 259 seconds), so we can't figure out what the blocking handler process was stuck in.
As Jingshan mentioned, a bigger debug buffer size on client should be helpful.
|
BTW, did you see any abnormal dmesg on the client and server nodes?
OSS dmesg:
Client dmesg:
|
|
Yes, this can explain why there are some log missed. We can use debug log daemon to address that. If performance is an issue, we can write the debug file into ramdisk.
Also it will help if you can monitor the vmstat in addition to RPC stats on the OSS nodes with:
and monitor RPC stats with:
|
|
Uploaded a tar file LU-874.debug_logs.1323124931.tar with debug data for the latest occurrence. This time I used lctl debug_daemon to capture more data. However, the OSS dmesg output mentions some debug daemon buffer overflows, so there may still be some missing entries. It was writing to a RAM disk. The tar file contains:
LU-874.dmesg.client
LU-874.dmesg.oss
LU-874.lustre-log.client.1323124931.txt.gz
LU-874.lustre-log.oss.1323124931.txt.gz
LU-874.rpcstats-zwicky4.log.gz
LU-874.vmstat-zwicky4.log.gz
|
|
I can make a conclusion that this issue is due to slowness on the OST. Let's take a look at lock with cookie: 0xfa0917560267023f, the corresponding client cookie is: 0xe7cb6d7040dca4a4.
Client enqueued this lock at:
and cancel it at:
which sent OST_WRITE RPC with xid: 1386945715233692, however, it cost obdfilter 122 seconds to handle this RPC:
Though the lock timeout is only 101 seconds:
The OST log was truncated so we couldn't understand why it took so long time for obdfilter to handle this RPC.
In the next step, let's apply a new set of debug parameters on the OST, I'll consult ldiskfs expert for suggestion.
|
|
If there is a bug that is causing OST slowness, we can address that in another jira ticket.
But in my experience, OST slowness is a frequent problem in production. No matter what we do to the OST code there will be times that it is slow.
The client has completely fulfilled its obligation. There is no good reason for evicting it.
So in this bug I would like us to look into fixing that basic problem.
|
|
In my point of view, the client was doing what it's supposed to do. From the log, the OST took longer than expectation to handle page writeback request. It's really difficult for this problem to be fixed at client side.
However, the slowness of OST was still symptom, we should dig the root cause out.
|
|
Is it possible to disable OSS read cache to see if we have a good luck?
|
Is it possible to disable OSS read cache to see if we have a good luck?
Sure, I'll report back with results.
|
|
As Ned said, we will look into that. But lets track anything about obdfilter slowness or OSS performance problems in another bug.
We really need to work on a solution to the problem here. As I undertand it, the server has a cancellation from the client sitting in its queue, but evicts the client anyway. That is a clearly a bug in the server.
I really think that the server really needs to either extend the ldlm timeout to an indefinite timeout time (-1 or something), or set an explicit flag in the lock that means "do not evict, cancellation is sitting in our queue".
We might consider making the cancel message high-priority, but I really don't have a full enough understanding of all of the corner cases to claim that we can do that safely.
|
We might consider making the cancel message high-priority, but I really don't have a full enough understanding of all of the corner cases to claim that we can do that safely.
I had the same idea to use a new portal for canceling (OST_WRITE) requests, but finally I found this won;t work. This is because lock canceling code has to evict all pages so it has to lock all covering pages, that means it doesn't help if some of pages are being written by page-writeback daemon because those RPCs will still be in normal portal at the server side.
|
|
Ah, sorry, I wasn't thinking it was the OST_WRITE that is the problem.
If I remember correctly, an OST_WRITE will extend a lock timeout, but perhaps only when it is actually processed. Is that correct? If so, we really need to extend the lock timeout while it is sitting in the queue.
I would think that an OST_WRITE would be in the at queue, so we could extend the at timer extension code to also extend lock timeouts...but the lock timer and the rpc time are not necessarily related.
Do we need an additional queue like the at timeout queue for lock timeout extension?
|
|
I see "ost_rw_prolong_locks()) refresh locks" lines in the OSS debug log, so I am going to start by assuming that the client is correctly attaching the lock handle to the OST_WRITE rpc.
If that is the case, the ldlm lock should be extended at "processing" time, just before the rpc is put on the hpreq queue. I am not 100% certain from the logs that this is happening, but I am going to assume that it is.
I believe that the only other time that the ldlm lock timeout is extended is at handling time.
There seems to be a basic faulty assumption here that the hpreq queue will always be handled in a short, bounded amount of time. This may often be true, but the system provides absolutely no guarantee of queue waiting time.
Therefore we MUST extend ldlm locks regularly while rpcs are sitting on the queues. If we do not, there will always be cases when we evict the clients even though the clients have done nothing wrong.
|
|
Yes, we should take queue waiting time into account, the final solution for this kind of problem is the implementation of resource control protocol or NRS; that is to say, clients should be told to not send any more requests because OST queue is over loaded.
|
|
NRS will help, but not solve the underlying problem. It will be capable of limiting the rate at which rpcs are enqueued, but not the rate at which they are dequeued. So NRS still leaves us with a design flaw that we need to address.
|
|
Furthermore, NRS introduces a NEW problem. Currently the clients cannot send any kind of early reply for ldlm lock revocations. The only way to extend an ldlm lock timeout is to put a bulk write into the server's queue. If NRS prevents a client from putting a bulk rpc into the queue for any length of time, it will increase the probability that the client will be evicted.
|
|
I don't know NRS in detail. But it's good to let the developers know the requirements. CC liang and andreas.
BTW, no message may mean good message. Disabling OSS read cache can fix this problem?
|
|
Disabling read cache is irrelevant as far as I can tell. We are not looking for a work-around, we are looking for a real fix to the problem.
|
|
there are lots of discussion about OSS read cache in LU-410 and LU-15. I'm going to pick it up and may ask for new stats to make sure we're hitting the same issue here.
|
|
I would prefer that someone work on THIS bug before dealing with OSS read cache problems.
|
|
Hi Chris,
I mentioned OSS read cache because we've seen this problem before. After OSS read cache is enabled, it will consume lots of memory which worsens the quality of IO on the OST side. This is why there were lots of "slow IO" warning messages printed. Unfortunately there is no decent way of fixing it instead of disabling OSS read cache. Sorry for confusion.
I have CC-ed this to wangdi who was taking care of this problem before.
|
|
The slowness of the OST can be dealt with elsewhere.
There will ALWAYS times that the OST is slow for some reason, be it OSS read cache, broken drives, whatever. Lustre has 512 IO threads. It is EASY to generate pathological IO patterns that drive the IO wait times into the minutes. Users do it all the time.
Lustre must behave correctly when this happens. This is probably the reason (or at least one reason) that we see evictions in production with 1.8 as well. We need to finally address the root problem here!
|
|
I agree that if the eviction is caused by slow IO on the server side, we probably should not punish client here. Just checking the code, actually in ost_rw_prolong_locks, it takes account in all of the "handling" time when update the timeout for lock.
/* prolong locks for the current service time of the corresponding
- portal (= OST_IO_PORTAL) */
opd.opd_timeout = AT_OFF ? obd_timeout / 2:
max(at_est2timeout(at_get(&req->rq_rqbd->
rqbd_service->srv_at_estimate)), ldlm_timeout);
&req->rq_rqbd->rqbd_service->srv_at_estimate includes all of the "processing" time of the rpc, which is from arriving to sent reply, so it should include the slow IO time here. I will investigate it further, probably some logic is not right here. Thanks.
|
|
Hi Chris,
This issue is our top priority now. We're discussing solution and will get back to you soon.
|
&req->rq_rqbd->rqbd_service->srv_at_estimate includes all of the "processing" time of the rpc, which is from arriving to sent reply, so it should include the slow IO time here. I will investigate it further, probably some logic is not right here. Thanks.
That is only true at a fixed point in time when the rpc is initially processed and enqueued. src_at_estimate is just a guess of how long the rpc processing will take based on the PAST information. The rpc processing time can, and often does, exceed the estimate.
With AT, the rpc timeout will be extended and the client will be sent an early reply so that it does not time out on the rpc. However the server fails to update the associated lock timeout when the rpc timeout is extended by the AT code.
We have a patch that we are testing tonight that extends the lock timeout whenever the AT code extends the rpc timeout. It is basically just a one-liner that calls ptlrpc_server_hpreq_check() from ptlrpc_at_check_timed() when it extends the AT timer. We'll let you know how it goes, and I'll push it to gerrit when I'm at work tomorrow.
|
|
Testing didn't show a significant improvement.
Since oss read cache seems to be making server-side log collection virtually impossible, we have disabled it. We'll see if the eviction bug is still reproducible without it.
|
|
Just 1 question - by any chance you're not mounting Lustre-FS directly on OSD? If that is the case, we ran into similar problems with spontaneous evictions and traced it back to that mount - we hit deadlock.
What we did as quick remedy: sync; echo 3 > /proc/sys/vm/drop_caches
And of course ideal case would be to not mount Lustre-FS directly on the server.
Can you see if that makes a difference?
|
|
Hi Chris,
I was going to take the lock out of waiting list, if there is a pending IO requests for that lock. But I regard your proposal as a better way by extending lock timeout each time when early replies are sent. Can you please describe the problem you met in testing a bit more detail?
|
|
Mike, no, our Lustre clients and OSSs are separate nodes.
|
|
In discussion today, the latest news in testing is that disabling the OSS read cache has avoided this problem. However, we'd like to understand the problem better, and so additional testing will be done to isolate the root cause. The first testing will try to determine whether threads-per-client < rpcs_in_flight will allow each thread to at least get some IO to the server. This can be achieved by increasing the client count and reducing threads per client (still 512 total threads), setting "lctl max_rpcs_in_flight=(2 * cores)", or some combination of both.
Sub task bugs have been filed to investigate the various different issues that have been discussed.
|
|
I may have been too quick to judge that disabling the OSS read cache avoided the problem. I still see evictions in the logs after I turned it off. I didn't manually flush the cache on the OSS nodes until Monday though, so if the cache doesn't clear out on its own in a reasonable fashion...
We need another clean run to make sure it is really unreproducible without OSS read cache. hype was taken for other testing, so we'll try to get testing running from alternate client shortly.
Also, I should probably clarify the reproducer. While initially it looks like a single-share-file run of IOR was the reproducer, we have seen it other times as well. file-per-process IOR has had evictions, and on PW locks spanning the entire file.
Also, a single IOR run will probably never reproduce this problem. We only see it when running the IO portion of the SWL suite, which runs many smaller IO jobs at the same time. Mostly IOR and simul jobs.
|
|
Can you please run the test with RPC trace enabled because we're going to analyze the IO model so as to generate similar scenarios to reproduce it in our lab?
|
|
We already have, look at the logs we provided. Unless you mean that you want us to trace every single node in the cluster, which seems rather difficult. Especially since we already know that logging on the server side is no good when problems happen...
|
|
Indeed, I'll use that log then.
Now that we're suspecting the problem is about IO quality, we should collect brw_stats on the obdfilter as well. Also there's another proc entry: writethrough_cache_enable of obdfilter, we should disable it as well. It has the same effect as read_cache_enable consuming a lot memory on the server side.
|
|
Ok, I think I can reproduce the problem like this. I create a job script with this contents:
Then I queue up many of those jobs by doing:
On one of our systems, three 16 node jobs can run at the same time. At some point we will have a server start spewing messages about "unable to allocate tage", which is why our logging on the servers is so ineffective. Usually there are also a fair number of slow io messages of various sorts. Somewhere in there we'll see evictions.
We really need to get to the bottom of the tage allocation issues. If we can't get server logs, it is going to be hard to debug this. Clearly there is some kind of memory pressure issue.
Note that we have OSS read cache DISabled, so that apparently was not the problem.
|
|
Ah, I did not disable writethrough_cache_enable, only read_cache_enable! That probably explains the huge cache usage I see.
|
|
Disabling writethrough_cache_enable in addition to disabling read_cache_enable does (at least for now) appear to have eliminated the "tage" allocation issues. We still do see the eviction, but now hopefully the server logs will not be missing lines.
We'll share logs when we get them.
|
|
I am seeing some decent 400MB logs (with debug_mb set to 1000) on the server side now. Not entirely certain if everything we need is in there though. There seems to be some strangeness. For instance, I am looking at a server log where it evicted a client, but the client seems oblivious to the eviction. Strange.
But anyway, maybe someone can explain LDLM lock flags to me. I am seeing the following.
2011-12-17 18:35:07.033418 00010000:00020000:8.1::0:0:0:(ldlm_lockd.c:356:waiting_locks_callback()) ### lock callback timer expired after 465s: evicting client at 192.168.121.115@o2ib2 ns: filter-lc3-OST0001_UUID lock: ffff8802643ddd80/0xe068980dd4dacbe7 lrc: 3/0,0 mode: PW/PW res: 93591578/0 rrc: 1739 type: EXT [24024973312->24058527743] (req 24024973312->24026021887) flags: 0x20 remote: 0x2b77fe919eba1dfa expref: 101 pid: 5002 timeout 5075017673
The lock callback timer expires at 18:35:07, supposedly after 465s.
Now looking back in the logs, I can't really tell where the server ever sends the lock callback. But I DO see plenty of "Luck dump" logs which contain this particular lock. It looks like the first time I see it in a debug log is here:
2011-12-17 18:27:43.531550 00010000:00000040:4.0::0:26699:0:(ldlm_lock.c:1896:ldlm_lock_dump()) -- Lock dump: ffff8802643ddd80/0xe068980dd4dacbe7 (rc: 2) (pos: 143) (pid: 5002)
2011-12-17 18:27:43.531551 00010000:00000040:4.0::0:26699:0:(ldlm_lock.c:1902:ldlm_lock_dump()) Node: NID 192.168.121.115@o2ib2 (rhandle: 0x2b77fe919eba1dfa)
2011-12-17 18:27:43.531552 00010000:00000040:4.0::0:26699:0:(ldlm_lock.c:1915:ldlm_lock_dump()) Resource: ffff8805ef88b1c0 (93591578/0/0)
2011-12-17 18:27:43.531553 00010000:00000040:4.0::0:26699:0:(ldlm_lock.c:1920:ldlm_lock_dump()) Req mode: PW, grant mode: PW, rc: 2, read: 0, write: 0 flags: 0x0
2011-12-17 18:27:43.531554 00010000:00000040:4.0::0:26699:0:(ldlm_lock.c:1926:ldlm_lock_dump()) Extent: 24024973312 -> 24058527743 (req 24024973312-24026021887)
It appears in various times, with little change but the "pos", which seems normal. the "flags" field remains 0x0. Up through an entry at 18:33:16. The next entry at 18:34:23 shows "flags" as 0x20:
2011-12-17 18:34:23.632487 00010000:00000040:3.0::0:7170:0:(ldlm_lock.c:1896:ldlm_lock_dump()) -- Lock dump: ffff8802643ddd80/0xe068980dd4dacbe7 (rc: 3) (pos: 119) (pid: 5002)
2011-12-17 18:34:23.632488 00010000:00000040:3.0::0:7170:0:(ldlm_lock.c:1902:ldlm_lock_dump()) Node: NID 192.168.121.115@o2ib2 (rhandle: 0x2b77fe919eba1dfa)
2011-12-17 18:34:23.632489 00010000:00000040:3.0::0:7170:0:(ldlm_lock.c:1915:ldlm_lock_dump()) Resource: ffff8805ef88b1c0 (93591578/0/0)
2011-12-17 18:34:23.632490 00010000:00000040:3.0::0:7170:0:(ldlm_lock.c:1920:ldlm_lock_dump()) Req mode: PW, grant mode: PW, rc: 3, read: 0, write: 0 flags: 0x20
2011-12-17 18:34:23.632491 00010000:00000040:3.0::0:7170:0:(ldlm_lock.c:1926:ldlm_lock_dump()) Extent: 24024973312 -> 24058527743 (req 24024973312-24026021887)
0x20 is LDLM_FL_AST_SENT. So somewhere between 18:33:16 and 18:34:23 the OSS must have at least thought about sending the lock blocking callback to the lustre client. Am I correct that LDLM_FL_AST_SENT means that the server tried to send an LDLM_BL_CALLBACK?
So there would appear to be a couple of problems here:
1) Less than two minutes before the eviction, the LDLM_FL_AST_SENT flag is not set, but the eviction message claims that we timed out after 465 seconds.
2) I don't see the rpc actually being sent before the eviction.
I uploaded zwicky3-lustre-log.1324175738.4930.txt.bz2. This is log from an OSS after evicting a client.
|
|
I just uploaded another file:
LU-874_incident2.tar.bz2
This tarball contains OSS and client log after an eviction, and a snippet from the console log. Interestingly, the console log shows the server receiving an ldlm_cancel from the client shortly after the OSS evicted the client and dumped its log.
I see several incidents like this in the log. Not all show a late ldlm_cancel, but some do.
|
|
At 4pm today I set
on all of the hype clients. We'll let you know tomorrow if that reduces the eviction rate.
|
I just uploaded another file:
LU-874_incident2.tar.bz2
This tarball contains OSS and client log after an eviction, and a snippet from the console log. Interestingly, the console log shows the server receiving an ldlm_cancel from the client shortly after the OSS evicted the client and dumped its log.
I see several incidents like this in the log. Not all show a late ldlm_cancel, but some do.
This is the best log so far. Can you please show me the brw_stats of this target if the system is still alive?
From what I have seen in the log, it;s the same problem. In the ost log:
00000100:00000040:2.0:1324236462.397570:0:5783:0:(lustre_net.h:1649:ptlrpc_rqphase_move()) @@@ move req "New" > "Interpret" req@ffff88030e242850 x1388386122264103/t0(0) o-1>b0e506da-bfef-9e48-4c5d-1a6e2f6ebec4@NET_0x50002c0a87808_UUID:0/0 lens 456/0 e 0 to 0 dl 1324237068 ref 1 fl New:H/ffffffff/ffffffff rc 0/-1
00000100:00000040:2.0:1324236462.397581:0:5783:0:(service.c:1686:ptlrpc_server_handle_request()) RPC GETting export ffff880336fc3c00 : new rpc_count 1
00000020:00000040:2.0:1324236462.397583:0:5783:0:(genops.c:748:class_export_get()) GETting export ffff880336fc3c00 : new refcount 6
00000100:00100000:2.0:1324236462.397586:0:5783:0:(service.c:1710:ptlrpc_server_handle_request()) Handling RPC pname:cluuid+ref:pid:xid:nid:opc ll_ost_io_205:b0e506da-bfef-9e48-4c5d-1a6e2f6ebec4+6:4166:x1388386122264103:12345-192.168.120.8@o2ib2:4
00000010:00000040:2.0:1324236462.397594:0:5783:0:(ost_handler.c:682:ost_rw_prolong_locks()) refresh locks: 93608461/0 (0->4095)
00000010:00010000:2.0:1324236462.397596:0:5783:0:(ost_handler.c:648:ost_prolong_locks_iter()) refresh lock: 93608461/0 (0->4095)
00010000:00010000:2.0:1324236462.397598:0:5783:0:(ldlm_lockd.c:545:ldlm_refresh_waiting_lock()) ### refreshed ns: filter-lc3-OST0001_UUID lock: ffff88037fb31000/0xe068980dd50a3110 lrc: 4/0,0 mode: PW/PW res: 93608461/0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->4095) flags: 0x20 remote: 0xa92445bc72b8b582 expref: 6 pid: 5049 timeout 5136015364
00002000:00001000:2.0:1324236462.397623:0:5783:0:(fsfilt-ldiskfs.c:1172:fsfilt_ldiskfs_map_ext_inode_pages()) inode 1304345234: map 1 pages from 0
00002000:00001000:2.0:1324236462.397625:0:5783:0:(fsfilt-ldiskfs.c:1141:fsfilt_map_nblocks()) blocks 0-0 requested for inode 1304345234
00000020:00000040:2.0:1324236462.397633:0:5783:0:(genops.c:748:class_export_get()) GETting export ffff880336fc3c00 : new refcount 7
00002000:00000040:2.0:1324236676.910061:0:5783:0:(lustre_fsfilt.h:255:fsfilt_brw_start_log()) started handle ffff880296fa01c8 ((null))
00002000:00000400:2.0:1324236676.910063:0:5783:0:(lustre_fsfilt.h:266:fsfilt_brw_start_log()) lc3-OST0001: slow journal start 214s
00002000:00000400:2.0:1324236676.910076:0:5783:0:(filter_io_26.c:718:filter_commitrw_write()) lc3-OST0001: slow brw_start 214s
00002000:00001000:2.0:1324236676.910094:0:5783:0:(fsfilt-ldiskfs.c:1172:fsfilt_ldiskfs_map_ext_inode_pages()) inode 1304345234: map 1 pages from 0
00002000:00001000:2.0:1324236676.910096:0:5783:0:(fsfilt-ldiskfs.c:1141:fsfilt_map_nblocks()) blocks 0-0 requested for inode 1304345234
00002000:00000040:2.0:1324236679.718023:0:5783:0:(fsfilt-ldiskfs.c:235:fsfilt_ldiskfs_set_version()) Set version 0xc581c9c (old 0x0) for inode 1304345234
00002000:00000040:2.0:1324236679.718027:0:5783:0:(filter.c:191:filter_finish_transno()) callback GETting export ffff880336fc3c00 : new cb_count 1
00000020:00000040:2.0:1324236679.718029:0:5783:0:(genops.c:748:class_export_get()) GETting export ffff880336fc3c00 : new refcount 11
00002000:00100000:2.0:1324236679.718039:0:5783:0:(filter.c:212:filter_finish_transno()) wrote trans 207101084 for client b0e506da-bfef-9e48-4c5d-1a6e2f6ebec4 at #75: err = 0
00002000:00000040:2.0:1324236679.718046:0:5783:0:(lustre_fsfilt.h:296:fsfilt_commit()) committing handle ffff880296fa01c8
Xid x1388386122264103 must be the RPC to write this 1-page size lock. This RPC was started at time 1324236462, but it wasn't finished even when the client was evicted(from client log, it was finished around 1324236721). One thing needs mentioning is that the target finished the trans 20 seconds later, because from the client log:
00000100:00100000:0.0:1324236700.329209:0:4168:0:(client.c:2304:ptlrpc_free_committed()) lc3-OST0001-osc-ffff880432428000: committing for last_committed 207101084 gen 1
It saw last commited transno 207101084 at 1324236700.
But I still don't understand why the whole transaction took 40 seconds to finish, so brw_stats may help.
|
|
Attach brw_stats from lc3-OST0001.
|
|
Please try this patch: http://review.whamcloud.com/1893
At least this patch will prevent clients from being evicted, but the real cause of why it takes so long time to finish an IO is still in investigation.
|
|
The above patch is just a 1st step, I'm working on simplifying: f31b79be5a0380df3ed05c16fa43feca2bf5905c
|
Attach brw_stats from lc3-OST0001.
From the stats, as a result of disabling read/writethrough cache, the fragmented IO is pretty good; though I didn't see this data before, this one looks really good.
However, the IO time is unreasonable high:
read | write
I/O time (1/1000s) ios % cum % | ios % cum %
1: 1045444 3 3 | 17037961 29 29
2: 198581 0 3 | 1628245 2 32
4: 410671 1 5 | 4428738 7 39
8: 400069 1 6 | 2406253 4 43
16: 975609 3 9 | 1868326 3 47
32: 2669569 8 18 | 1941762 3 50
64: 4080490 13 31 | 2314273 3 54
128: 2989028 9 40 | 3216968 5 59
256: 2313183 7 48 | 4901037 8 68
512: 3168275 10 58 | 6715429 11 79
1K: 5031839 16 74 | 6745534 11 91
2K: 5563808 17 92 | 3871176 6 98
4K: 2388908 7 99 | 645984 1 99
8K: 86744 0 99 | 247488 0 99
16K: 33 0 100 | 95456 0 99
32K: 0 0 100 | 38983 0 99
64K: 0 0 100 | 26497 0 99
128K: 0 0 100 | 15638 0 99
256K: 0 0 100 | 9393 0 99
512K: 0 0 100 | 3685 0 99
1M: 0 0 100 | 132 0 100
I guess this is because the disk is quite busy - 50% percent time there are over 32 requests in flight. This is no good, we should work out a flow control algorithm to stop sending low prio requests to a target if it's pretty busy.
|
Please try this patch: http://review.whamcloud.com/1893
At least this patch will prevent clients from being evicted, but the real cause of why it takes so long time to finish an IO is still in investigation.
If I understand correctly, the fix is the moving of the ptlrpc_hpreq_fini() calls, and the rest is just clean up. Moving the ptlrpc_hpreq_fini() call leaves the message on the exp_queued_rpc queue which should allow the ldlm_lock_busy() to find the rpc, which in turn allows waiting_locks_callback() to extend the lock rather than timing out.
Is that correct?
I'll give it a try.
|
|
Hi Chris,
Yes, you're right. Another fix in the patch is to match extent exactly.
|
|
I've graphed the stats from comment-24967 in 874pdf.pdf
If I'm interpreting these stats correctly, all reads and the vast bulk of writes complete within 16 seconds, but some writes are taking many minutes. We really need an explanation for these long running writes - what is causing the long delay (memory allocation? elevator? storage device?) and why aren't reads similarly affected?
As an aside, I'm also surprised at the high proportion of writes that complete in <= 1mS. I assume this means the storage device is write-back rather than write-thru?
|
|
I've also graphed pages per RPC and I/O here to compare the number of pages
per bulk RPC with the disk I/O sizes.
1. You can see many more single-page reads and writes than there were single-page RPCs.
2. Multi-page rpcs and disk writes seem identical, but multi-page rpcs and reads differ visibly
3. Why are we sending significant numbers of 16 page writes.
|
As an aside, I'm also surprised at the high proportion of writes that complete in <= 1mS. I assume this means the storage device is write-back rather than write-thru?
Yes, the storage controller uses a write-back cache with battery protection.
|
|
The patch shows promise, but our testing has been weak so far. We've started hitting ldiskfs panics that we've never seen before. On the assumption that the panic is LU-508, I've pulled in that fix and will try again.
|
|
The purpose of this patch is to let you move forward while we're working on it. We still don't know the root cause of this problem, so the fixing time is uncertain.
You can also try the 2nd version of patch, it can reduce lock contention on the obdfilter.
|
|
Ok. The SWL is running now, and I want to let that get a few hours in on the previous patch to have a little more confidence in the fix. We are upgrading the client side in a few hours, so I'll prep the second patch to be installed on the servers then. Then we will run the IO portion of the SWL over night.
|
|
It looks like we are still seeing evictions with the first patch from http://review.whamcloud.com/1893.
|
|
Uploaded OSS log zwicky4-lustre-log.1324422741.5007.txt.bz2 to ftp.whamcloud.com.
|
|
Just talked with jinshan. As for slow IO, there are still a few things we are not clear yet.
1. In brw_stats
disk fragmented I/Os ios % cum % | ios % cum %
0: 37702 0 0 | 0 0 0
1: 21280221 67 68 | 46004699 79 79
2: 9716371 31 99 | 12153872 20 99
3: 218670 0 99 | 351 0 99
4: 38716 0 99 | 33 0 99
So there are still 20% I/O is fragmented. And we do not know why. Could you please tell me what is the storage you use on that OSS? What is the max_hw_segments setting on that OST?
2. In your script, it does
#!/bin/bash
srun o job%J.log /g/g0/morrone/src/ior/src/ior -t 128M -b 256M -e -C -g -o /p/lcrater3/morrone/test.$SLURM_JOBID
sbatch -O -N 16 -n 256 mytestscript
Do you mean you just keep launching this script, you can see the slow IO and client eviction? Are there any other jobs which drives OSS busy as well? Could you please tell us more about these jobs.
|
|
Do you disable read only cache and write through cache in the latest run? I'm looking at the log, it appears to the first one where useful information were lost.
|
|
Yes, I doubled checked and both read and writethrough cache are disabled.
|
Do you mean you just keep launching this script, you can see the slow IO and client eviction?
Yes, that is correct. I issue that several hundred times with the sbatch command that I provided.
The SWL IO load is a more reliable and frequent reproducer of the slow IO and evictions, so that is mainly what we have running on hype right now. That is a mix of many sizes of IORs and simul, and mdtest, and may do some logging of it own output into lustre.
Could you please tell me what is the storage you use on that OSS?
One NetApp enclosure with 2 controllers and 60 drives. The drives are grouped into RAID6 arrays of 10 drives. 6 LUNS total. Two OSS are each IB connected to both controllers. Each OSS is primary for 3 OSTs.
What is the max_hw_segments setting on that OST?
max_segments is 255. max_hw_sectors_kb is 32767.
|
|
brw_stats for all three OST on zwicky3 about three hours after startup.
|
Yes, that is correct. I issue that several hundred times with the sbatch command that I provided.
Note that those jobs run IN PARALLEL, at least three at any given moment. If you just run IOR jobs sequentially, you may never see this.
|
I'm looking at the log, it appears to the first one where useful information were lost.
No, thats pretty normal. I've been only passing on logs that looked like they might be useful before now. This one I just passed on without looking at it first.
Think about what you need to know, add logging, and we'll test it. I think thats the only way we are going to make progress on this.
|
|
Possibly this is just a result of temporary hangs due to slow io on the servers, but I thought I should mention that this is happening fairly frequently on the clients:
|
Uploaded OSS log zwicky4-lustre-log.1324422741.5007.txt.bz2 to ftp.whamcloud.com.
From this log, I didn't see any attempt from client side to write back pages back.
|
|
True. We may have more than one issue here. We'll just have to see what happens overnight. Too soon to say.
|
|
Something is very odd here. I just saw a single OST evict nine different nodes. But none of those nodes appear to know that they were evicted.
And yet ANOTHER client did think it was evicted and drop its log. I will attach a tarball.
|
|
Uploading LU-874_incident3.tar.bz2 to ftp site.
|
|
Sorry, didn't include the decoded hype log. Better tar ball is LU-874_incident3.2.tar.bz2.
|
I'm looking at the log, it appears to the first one where useful information were lost.
No, thats pretty normal. I've been only passing on logs that looked like they might be useful before now. This one I just passed on without looking at it first.
Think about what you need to know, add logging, and we'll test it. I think thats the only way we are going to make progress on this.
Sure, please try the patch set 4 at: http://review.whamcloud.com/#change,1893. In this patch, I removed ldlm_resource_dump() so as to have more room for useful log on the server side.
In the latest run, the most strange thing is that there is no 'slow IO' or 'prolong' information any more, neither RPC was sent for lock cancel, it looks very like that the client is simply hung. This seems to be a good sign to me.
So, please do the following things in the next run:
1. dump log on the server, and find the cookie of eviction, then find the corresponding client and dump the log; If there are multiple evictions, please choose the latest ones; also, please dump log from 2~3 clients so that we can have a greater chance to find an useful log;
2. Please collect RPC(ost.OSS.ost_io.{stats|high_priority_ratio) and BRW stats with timestamp;
3. Please send me the backtrace of tasks on the hung clients;
4. Be sure to clear stats before starting the test.
Thanks.
|
|
hmm.. It had the message of 'prolong the busy lock' in the log.
Is it always the same OSS to run into problem?
|
|
For log LU-874_incident3.2.tar.bz2, let's take a look at cookie: 0x54e8463975d1f617. At the client side, this lock was cancelled by process 7097, and it doesn't have dirty pages caching, so the lock was cancelled directly at: 1324434349.564787 with lock cancel RPC: x1388756785471675, but the reply was never received. Also, there is no such request appeared on the server side.
Does it mean there is a problem with network?
|
|
FYI, LU-508 didn't eliminate the panic in ldiskfs. We are looking in to that now. Unfortunately crash dump is currently broken. But we'll work on it.
|
|
after taking a closer look at the log, the canceling RPC is not just handled. From the log, the last LDLM_CANCEL from this client is handled:
00000100:00100000:3.0:1324434397.956059:0:5931:0:(service.c:1756:ptlrpc_server_handle_request()) Handled RPC pname:cluuid+ref:pid:xid:nid:opc ldlm_cn_17:8ae6de69-cd06-890c-9fa3-d599737105f8+97:7069:x1388756785471672:12345-192.168.121.80@o2ib2:103 Request procesed in 50354207us (50472837us total) trans 0 rc 0/0
00000100:00100000:3.0:1324434460.924634:0:5945:0:(service.c:1709:ptlrpc_server_handle_request()) Handling RPC pname:cluuid+ref:pid:xid:nid:opc ldlm_cn_31:8ae6de69-cd06-890c-9fa3-d599737105f8+90:7071:x1388756785471674:12345-192.168.121.80@o2ib2:10
it took 50 seconds to handle that request. From the client log, this request was sent at:
00000100:00000040:5.0:1324434347.334213:0:7069:0:(lustre_net.h:1649:ptlrpc_rqphase_move()) @@@ move req "New" > "Rpc" req@ffff88037c0ba400 x1388756785471672/t0(0) o-1>lc3-OST0002_UUID@10.1.1.4@o2ib9:17/18 lens 296/192 e 0 to 0 dl 0 ref 2 fl New:N/ffffffff/ffffffff rc 0/-1
00000100:00100000:5.0:1324434347.334218:0:7069:0:(client.c:1395:ptlrpc_send_new_req()) Sending RPC pname:cluuid:pid:xid:nid:opc ldlm_bl_07:8ae6de69-cd06-890c-9fa3-d599737105f8:7069:1388756785471672:10.1.1.4@o2ib9:103
00000100:00000040:5.0:1324434347.334225:0:7069:0:(niobuf.c:681:ptl_send_rpc()) @@@ send flg=0 req@ffff88037c0ba400 x1388756785471672/t0(0) o-1->lc3-OST0002_UUID@10.1.1.4@o2ib9:17/18 lens 296/192 e 0 to 0 dl 1324434570 ref 3 fl Rpc:N/ffffffff/ffffffff rc 0/-1
00000100:00000040:5.0:1324434347.334229:0:7069:0:(niobuf.c:63:ptl_send_buf()) conn=ffff88041e6f5f40 id 12345-10.1.1.4@o2ib9
00000100:00100000:5.0:1324434347.334240:0:7069:0:(client.c:1993:ptlrpc_set_wait()) set ffff88037b0d4940 going to sleep for 208 seconds
00000100:00000040:2.0:1324434347.334322:0:4747:0:(client.c:2168:__ptlrpc_req_finished()) @@@ refcount now 2 req@ffff88037c0ba400 x1388756785471672/t0(0) o-1->lc3-OST0002_UUID@10.1.1.4@o2ib9:17/18 lens 296/192 e 0 to 0 dl 1324434570 ref 3 fl Rpc:N/ffffffff/ffffffff rc 0/-1
This may be due to the contention at resource lock. Can you please monitor the CPU overhead on the OSS, and it will be better if you can use oprofile to verify if there is heavy contention at resource lock.
Another option is to try patch set 3 at http://review.whamcloud.com/#change,1893 where I use interval tree to reduce contention on resource lock.
|
|
I mentioned this in person, but just to record it here: the panics are believed to be unrelated.
|
|
This morning I started looking in to this issue too. I started by carefully tracing the lock cookie 0x54e8463975d1f617 from your previous comment. What I see in the logs for this request is that the server a blocking cancel to the client as xid 1388750491010582 for lock handle 0x54e8463975d1f617. The client cancels this quickly because there is no dirty data, just as you said, and sends its cancel rpc as xid x1388756785471675 back to the server.
Now this second xid doesn't appear in the server logs but I don't think it's because of a network issue. The server log just doesn't go back far enough in time. If you notice that first blocking cancel 1388750491010582 doesn't show up in the server log either. Both of these events just occurred before the log starts.
Chris is going to apply your latest patch and increase the log size so we can get the critical bit of data about how the server (mis)handled the cancel.
|
|
Patchset 4 of http://review.whamcloud.com/1893 is on, and debug_mb has been increased. Just waiting for the next eviction.
|
|
Just post the patch http://review.whamcloud.com/#change,1899 for reserving pages for each OSS threads, Could you please add it to see whether it could alleviate fragmented IO problem, which might be one reason for slow IO? Thanks.
|
|
As a general rule, it isn't worthwhile to apply a patch for testing unless it has already passed our own autotest suite. Otherwise it is wasting everyone's time and effort. Please hold off applying change 1899 until it has gotten the OK from Maloo.
|
|
Uploading (it is taking a while) LU-874_incident4.tar to ftp site. Latest hit. Very large debug log from OSS.
I'll add http://review.whamcloud.com/#change,1899 next.
|
Now this second xid doesn't appear in the server logs but I don't think it's because of a network issue. The server log just doesn't go back far enough in time. If you notice that first blocking cancel 1388750491010582 doesn't show up in the server log either. Both of these events just occurred before the log starts.
Yes, I made that conclusion too quick. After taking a closer look, I found this may be a lock contention issue on the server because it took around 50 seconds to handle the previous LDLM_CANCEL with xid x1388756785471672 from the same client(please take a look at comment at: 21/Dec/11 1:40 PM); the server just didn't get a chance to handle it.
So I suspect the server was experiencing the following issue:
1. resource lock contention;
2. CPU load is pretty high, otherwise there would be another ldlm callback thread to handle that requst.
In the new run, I'm asking for monitoring server CPU usage, RPC stats and better oprofile it to see if there exists heavy contention on ldlm resource lock.
Thanks for helping.
|
Uploading (it is taking a while) LU-874_incident4.tar to ftp site. Latest hit. Very large debug log from OSS.
take a look at xid x1388756786783757, this is the LDLM_CANCEL request from client side. It looks like it wasn't handled in time so early reply was sent. Unfortunately, the lock timed out in the waiting list soon at 1324507012.765655.
00000100:00000040:6.0:1324506980.312259:0:4098:0:(events.c:284:request_in_callback()) incoming req@ffff88062737d000 x1388756786783757 msgsize 296
00000100:00001000:8.0:1324506993.802831:0:6063:0:(service.c:978:ptlrpc_at_send_early_reply()) @@@ sending early reply (deadline +10s, margin 140s) for 150+30 req@ffff88062737d000 x1388756786783757/t0(0) o-1>a6f0cdd7-033b-4d74-afd4-eb1f173a8216@NET_0x50002c0a87962_UUID:0/0 lens 296/0 e 0 to 0 dl 1324507003 ref 2 fl New:/ffffffff/ffffffff rc 0/-1
00000100:00000040:9.0:1324507026.661189:0:5798:0:(lustre_net.h:1649:ptlrpc_rqphase_move()) @@@ move req "New" > "Interpret" req@ffff88062737d000 x1388756786783757/t0(0) o-1>a6f0cdd7-033b-4d74-afd4-eb1f173a8216@NET_0x50002c0a87962_UUID:0/0 lens 296/0 e 1 to 0 dl 1324507143 ref 1 fl New:/ffffffff/ffffffff rc 0/-1
00000100:00100000:9.0:1324507026.661196:0:5798:0:(service.c:1709:ptlrpc_server_handle_request()) Handling RPC pname:cluuid+ref:pid:xid:nid:opc ldlm_cn_88:a6f0cdd7-033b-4d74-afd4-eb1f173a8216+5:5248:x1388756786783757:12345-192.168.121.98@o2ib2:103
00000100:00000040:9.0:1324507026.661210:0:5798:0:(lustre_net.h:1649:ptlrpc_rqphase_move()) @@@ move req "Interpret" > "Complete" req@ffff88062737d000 x1388756786783757/t0(0) o-1>a6f0cdd7-033b-4d74-afd4-eb1f173a8216@NET_0x50002c0a87962_UUID:0/0 lens 296/192 e 1 to 0 dl 1324507143 ref 1 fl Interpret:/ffffffff/ffffffff rc 116/-1
00000100:00100000:9.0:1324507026.661217:0:5798:0:(service.c:1756:ptlrpc_server_handle_request()) Handled RPC pname:cluuid+ref:pid:xid:nid:opc ldlm_cn_88:a6f0cdd7-033b-4d74-afd4-eb1f173a8216+4:5248:x1388756786783757:12345-192.168.121.98@o2ib2:103 Request procesed in 24us (46348957us total) trans 0 rc 116/116
00000100:00001000:9.0:1324507026.661219:0:5798:0:(service.c:1773:ptlrpc_server_handle_request()) @@@ sent 1 early replies before finishing in 46s req@ffff88062737d000 x1388756786783757/t0(0) o-1->a6f0cdd7-033b-4d74-afd4-eb1f173a8216@NET_0x50002c0a87962_UUID:0/0 lens 296/192 e 1 to 0 dl 1324507143 ref 1 fl Complete:/ffffffff/ffffffff rc 116/-1
Similar with BRW requests, it looks like we should prolong locks if the cancel requests are already in queue. I'll cook a patch soon.
|
|
FYI, I don't think we will learn much from oprofile.
Just watching the node with top, it rarely uses more than 15% of CPU time, although of course the rest of the idle time can frequently be attributed to iowait.
I do note (using "perf record") that of the small amount of CPU time that is used, the ldlm_callback_handler is frequently in ost_brw_lock_get.
|
|
Please try patch: http://review.whamcloud.com/1900
This patch will prioritize cancel request as what we have done for BRW requests.
Hi Chris,
just want to be sure, you didn't see significant time being used on spin_lock, right? otherwise, I'm wondering why it ever took 50 seconds to handle dlm cancel request.
|
|
Yes, I agree. The new server logs pretty clearly show that we just failed to extend the timeout on the server for the LDLM_CANCEL request which was sitting in the queue. I'm somewhat surprised we didn't think of this case when the hpreq handlers were introduced to originally resolve this same basic eviction issue. We only targeted the bulk requests and ignored the actual cancel requests. I suppose at the time this probably addressed the majority of the problem.
Regardless, we should register a srv_hpreq_handler for the ldlm service. This would allow us to selectively flag the LDLM_CANCEL request as high priority so it gets added to the request export list. The timer will then get properly extended using the same mechanism the bulks use which is a pretty clean fix. Alternately, we could extend the timeout when the early reply is sent but that seems slightly less clean to me since we already have the existing hpreq infrastructure for this.
Anyway, it sounds like your already cooking up a patch. I'll be happy to review whatever you come up with.
— Summary —
LOCK HANDLE: 0xbb499b404f76e69b - ffff8805e8589b40/0xef2323d516d588e2
BL_AST: xid=1388842889277109
BULK: xud=1388756786783710
CANCEL: xid=1388756786783757
— Logs —
SERVER 1324506831.432468:0:5011:0:(ldlm_lockd.c:791:ldlm_server_blocking_ast()) ### server preparing blocking AST ns: filter-lc3-OST0004_UUID lock: ffff8805e8589b40/0xef2323d516d588e2 lrc: 4/0,0 mode: PW/PW
SERVER 1324506831.432474:0:5011:0:(ldlm_lockd.c:457:ldlm_add_waiting_lock()) ### not re-adding to wait list(timeout: 100, AT: on) ns: filter-lc3-OST0004_UUID lock: ffff8805e8589b40/0xef2323d516d588e2 lrc: 4/
SERVER 1324506831.432494:0:5011:0:(client.c:1395:ptlrpc_send_new_req()) Sending RPC pname:cluuid:pid:xid:nid:opc ll_ost_73:lc3-OST0004_UUID:5011:1388842889277109:192.168.121.98@o2ib2:104
CLIENT 1324506831.445065:0:5089:0:(service.c:1708:ptlrpc_server_handle_request()) Handling RPC pname:cluuid+ref:pid:xid:nid:opc ldlm_cb_00:LOV_OSC_UUID+5:5011:x1388842889277109:12345-10.1.1.4@o2ib9:104
CLIENT 1324506831.450090:0:5065:0:(client.c:1395:ptlrpc_send_new_req()) Sending RPC pname:cluuid:pid:xid:nid:opc ptlrpcd-brw:a6f0cdd7-033b-4d74-afd4-eb1f173a8216:5065:1388756786783710:10.1.1.4@o2ib9:4
SERVER 1324506831.432953:0:5011:0:(client.c:1729:ptlrpc_check_set()) Completed RPC pname:cluuid:pid:xid:nid:opc ll_ost_73:lc3-OST0004_UUID:5011:1388842889277109:192.168.121.98@o2ib2:104
SERVER 1324506831.437952:0:4098:0:(events.c:284:request_in_callback()) incoming req@ffff880634adc000 x1388756786783710 msgsize 456
SERVER ... MISSING BULK HANDLING?!? BUT THE CLIENT DID GET A SUCCESSFUL WRITE AFTER ~148 SECONDS
SERVER 1324506980.310933:0:5839:0:(service.c:1756:ptlrpc_server_handle_request()) Handled RPC pname:cluuid+ref:pid:xid:nid:opc ll_ost_io_250:a6f0cdd7-033b-4d74-afd4-eb1f173a8216+5:5065:x1388756786783710:12345-192.168.121.98@o2ib2:4
CLIENT 1324506980.324793:0:5065:0:(client.c:1729:ptlrpc_check_set()) Completed RPC pname:cluuid:pid:xid:nid:opc ptlrpcd-brw:a6f0cdd7-033b-4d74-afd4-eb1f173a8216:5065:1388756786783710:10.1.1.4@o2ib9:4
CLIENT 1324506980.325692:0:5248:0:(client.c:1395:ptlrpc_send_new_req()) Sending RPC pname:cluuid:pid:xid:nid:opc ldlm_bl_02:a6f0cdd7-033b-4d74-afd4-eb1f173a8216:5248:1388756786783757:10.1.1.4@o2ib9:103
SERVER 1324506980.312259:0:4098:0:(events.c:284:request_in_callback()) incoming req@ffff88062737d000 x1388756786783757 msgsize 296
SERVER 1324506993.802831:0:6063:0:(service.c:978:ptlrpc_at_send_early_reply()) @@@ sending early reply (deadline +10s, margin 140s) for 150+30 req@ffff88062737d000 x1388756786783757/t0(0) o-1>a6f0cdd7-033b-4d74-afd4-eb1f173
-
-
-
-
-
- 1324507012.765655:0:0:0:(ldlm_lockd.c:356:waiting_locks_callback()) ### lock callback timer expired after 181s: evicting client at 192.168.121.98@o2ib2 ns: filter-lc3-OST0004_UUID lock: ffff8805e858
SERVER 1324507026.661196:0:5798:0:(service.c:1709:ptlrpc_server_handle_request()) Handling RPC pname:cluuid+ref:pid:xid:nid:opc ldlm_cn_88:a6f0cdd7-033b-4d74-afd4-eb1f173a8216+5:5248:x1388756786783757:12345-192.168.121.98@o2ib2:103
CLIENT 1324507026.675449:0:5248:0:(client.c:1729:ptlrpc_check_set()) Completed RPC pname:cluuid:pid:xid:nid:opc ldlm_bl_02:a6f0cdd7-033b-4d74-afd4-eb1f173a8216:5248:1388756786783757:10.1.1.4@o2ib9:103
|
|
Nice! You implemented what I was asking for even before I could post my comment. We'll give it a spin thanks!
|
|
How is the latest patch?
Can I have these stats?
1. RPC and BRW stats with timestamp I mentioned before
2. stats for jbd2 - it's located at /proc/fs/jbd2/<disks>/info
also can you please share me the elevator algorithm you're using for the storage?
|
|
Further note - can you confirm that we have a set of brw_stats taken after all (a) caching was disabled on the OSS and (b) brw_stats were reset or modules were reloaded.
Can you also telnet into the Pike's Peak controller (Chris Morrone knows how) and run 'luall' to list volume group average and max latencies and also 'luall 3' to list individual volume latencies and post the output here.
Thanks.
|
|
luall doesn't show much, just "OldestCmd Age(ms)". And this command shows stats per DRIVE, not per volume/lun.
The worst appears to be 21ms.
"luall 3" shows read and write "ART(us)" and "MRT(us)" times for all drives. I am assuming that ART is average, and MRT is max...what "RT" means exactly I am unsure.
For reads, worst ART is around 16000, and worst MRT is 1000000 (1s).
For writes, worst ART is around 45000, and worst MRT is 10000000 (10s). The 10s looks anomalous, most MRTs are 1s or less. The ART for the 10s drive is a little high at 1s, but not too far out of line with some of the others.
|
|
We use the default elevator, whatever that is.
Wow, you guys really seem more concerned about the slow io than we are. If Ned or Brian has time tomorrow perhaps they can get brw_stats or jbd2 info. But our motivation is low to figure out the performance with ldiskfs on this hastily thrown together test system. We are really busy, and should spend any performance investigation time on Orion and ZFS.
can you confirm that we have a set of brw_stats taken after all (a) caching was disabled on the OSS and (b) brw_stats were reset or modules were reloaded.
Yes, the second brw_stats that I attached to this bug was after running for about 3 hours after a fresh reboot of the servers with lustre's writethrough_cache_enable=0 and read_cache_enable=0:
http://jira.whamcloud.com/secure/attachment/10694/zwicky3_brw_stats.txt
|
|
We did get an eviction after some testing today with . Unfortunately, they rebooted the clients and I didn't know about it. Debug settings were not enabled on the client, so I only have a server log. I will upload that soon. We'll probably hit it again overnight, and Ned can gather logs for us tomorrow.
|
|
Uploading server log to zwicky4-lustre-log.1324601430.5293.txt.bz2
Note that we had the following two patches applied:
http://review.whamcloud.com/1893 (patch set 4)
http://review.whamcloud.com/1900 (patch set 1)
We didn't try 1899 yet.
|
|
I already know the problem, I'll cook a patch for this.
|
|
It looks like another failure mode where the client already had the writes outstanding before the blocking AST was issued? I see write RPCs that started before the blocking AST, but finished long after it (shortly before the lock timeout).
So the client may have had no additional dirty data to flush, so nothing winds up in the hpreq queue.
Is that your assessment?
Do you think the patch will be ready to try in the next hour or two? If so, I can put it on the servers tonight. Otherwise it will have to wait for Ned or Brian in the morning.
|
|
The problem is that we should refresh lock timeout after the request is finished - instead of refreshing it while the request is being handled, otherwise it exists a race that the lock times out immediately after we take the request out of HP list.
The correct way is to take the corresponding locks out of waiting list if HP RPCs are sitting in the queue, and after HP RPCs have been finished, we will add them back into waiting list, with a new lock timeout so that clients will have enough time to send dlm cancel request.
This patch will be a bit more complex than others, so that I will need more time.
|
|
I realize I can work out a workaround patch. Stay tuned.
|
|
Please try this patch if you're still there: http://review.whamcloud.com/#change,1893,patchset=5, plus patch: http://review.whamcloud.com/1900
|
|
That might be ok, but is it sufficient? In the server log that I supplied, the server appears to have begun handling write RPCs from the client BEFORE the conflicting lock enqueue triggered the blocking AST. So the client can't cancel the lock because it has writes outstanding, but those writes are not on the server's hpreq queue because they were sent before the client new about the blocking AST.
And since the writes are not on the hpreq queue, they don't go on the exp_queued_rpc list.
In the most recent server log, extending the lock timeout after the write is "Handled" might have avoided the eviction (but maybe not, without the time extension at "Handling" time, it may have timed out before "Handled"). But what if the handling time was longer still? The lock would still have timed out.
We probably need your new patch and our old patch to extend the lock timeout at AT early reply time as well. I was thinking that we didn't need our patch anymore with your http://review.whamcloud.com/1893 patch, but now I think we need both, since messages in the normal request queue are not on the export list.
|
That might be ok, but is it sufficient? In the server log that I supplied, the server appears to have begun handling write RPCs from the client BEFORE the conflicting lock enqueue triggered the blocking AST. So the client can't cancel the lock because it has writes outstanding, but those writes are not on the server's hpreq queue because they were sent before the client new about the blocking AST.
And since the writes are not on the hpreq queue, they don't go on the exp_queued_rpc list.
exp_queued_rpc contains all BRW, punch and LDLM_CANCEL requests to this export(please take a look at ptlrpc_hpreq_init() and ost_hpreq_handler() where rq_ops is assigned if the request is BRW and punch). For the scenario you mentioned, ldlm_lock_busy() will help us prolong lock timeout value.
|
|
I see, thanks! So not all BRW will wind up on the hpreq queue, but they all are put on the per-export list. Except for a BRW that is 0 sized or OBD_BRW_SRVLOCK is set, in which case we don't care.
In that case, this does seem like the correct approach.
|
|
We got an eviction after about 4 hours. Actually two clients were evicted, one on 4 different locks, the other on one lock. Uploading lu874-2011-12-23.tar.gz which has logs for the OSS and both clients. Also included are console snippets, rpcstats, brw_stats, and jbd2 stats.
|
|
I didn't find a lot of useful information in the last log. Please check the new patch at: http://review.whamcloud.com/#change,1893,patchset=6 where I added more debug information. Please make sure you have the following settings before running the patch:
1. apply the above patch and http://review.whamcloud.com/#change,1900,patchset=1
2. disable read only cache and write through cache
3. clear and collect RPC and BRW stats
Thanks.
|
|
We are back from the holidays. Ned has put that on zwicky, and we'll let you know how it goes.
|
|
The clients on hype are having non-lustre related problems, so I used the zwicky clients (46 or so nodes) with my own IOR workload. It ran all night, and didn't see a single eviction. That looks like an improvement.
I have started looking at the logs that Ned posted from Dec 23. It looks to me like this happens:
It is suspicious that we do not see the client sending an LDML_CANCEL in response to the LDLM_BL_CALLBACK. Could this be a client-side problem?
|
|
Hmmm, wait, I think I got confused on that time line.
Oddly there appears to be no record of the server sending the blocking ast for this particular lock.
|
|
Yes, so please run the job again with my latest patch where I added more debug information.
|
|
We have been. Like I said we installed that on Jan 2. I cannot currently reproduce the problem from the zwicky clients. We just got time on the hype clients again, so we will see if hype can reproduce it.
|
|
Yes, we got a hit with hype. Uploading this tarball now:
|
|
It looks much like the previous log, but a little clearer because on the server side the RPC that sends the LDLM_BL_CALLBACK is clear, as is the receipt on the client side. It certainly looks like the client fails to asynchronously run the AST handler before it is evicted.
|
|
Thanks, Chris.
From the latest log, it looks like ldlm_bl_XX threads were all busy in canceling locks, you can make it sure by running:
and check timestamp. RPC type 103 is LDLM_CANCEL. This is the root cause why it took so long time for the client to response blocking request of dlm lock: 0xcf6cea5a43ee80a.
But what made it so slow for the server to handle cancel request. Let's take a look at request x1390025835073007. This RPC was handled by ldlm_cn_08 on the server side. It clearly showed it had been blocked at ost_blocking_ast() because it had to write data in synchronous mode. In ost_blocking_ast():
This piece of code was imported in bug 16919. Unfortunately it's not easy to fix this problem. I would like to disable sync_on_lock_cancel by writing "never" into OST's sync_on_lock_cancel proc entry, but this will cause data corruption. So the safer solution is to disable async journal on the OST side - let's go back to stone age  .
|
|
Maybe we are on the wrong way to fix this whole thing. If there were no slow IO problem, we wouldn't need those patches at all. We've already got stats for storage, it will help if someone can take a look at it.
|
|
Well, sure, the client is busy canceling locks. But why did the client not even call ldlm_handle_bl_callback() until after its eviction?
There are only a couple of reasons that we would fail to create a new ldlm_bl_* thread to handle this work item and call ldlm_handle_bl_callback():
- We've hit max thread count
- cfs_create_thread() fails (although we would get a CERROR for this case that I don't see)
- blwi->blwi_mem_pressure is true
It doesn't look like blwi->blwi_mem_pressure should be set ever. I am not really understanding that yet.
Of the clients currently running, the largest count of ldlm_bl_ threads is currently 60. Since these nodes have 16 processors, the max thread count should be 128. If we had more pending ldlm_bl_ work items, why were more threads not created?
|
|
Oh! Nevermind, I completely see why more threads aren't starting. In the while(1), if the thread is able to get work it will never try to start more threads. It is only when it has to sleep and wakes up that it tries launching more threads. So that looks like any easy fix. I'll try it out.
|
|
it called ldlm_handle_bl_callback() by thread ldlm_bl_05 at the client side:
cookie 0xcd56b148db513809 is the client dlm cookie caused eviction on the server side. Process 3837 is ldlm_bl_05. However, it run ldlm_handle_bl_callback() at 1325717854.403101 the server has already evicted this client. ldlm_bl_05 was busy in canceling 0xcd56b148db5137df and RPC x1390025835073007 was the LDLM_CANCEL request:
look at the timestamp, it started to send the rpc at 1325717749.546139, and it was finished at 1325717854.40306. (Immediately it then started to handle the dlm lock caused the eviction).
Then I checked all other ldlm_bl_ threads and found they were in similar situation at that time:
check the process name and process id and timestamp you will see it.
Then I searched and tracked x1390025835073007 in the server log, and made that conclusion.
|
Oh! Nevermind, I completely see why more threads aren't starting. In the while(1), if the thread is able to get work it will never try to start more threads. It is only when it has to sleep and wakes up that it tries launching more threads. So that looks like any easy fix. I'll try it out.
Indeed, that implementation is buggy. It's a good try to fix it. However, I suspect we will always fall into this situation no matter how many threads you have.
|
Indeed, that implementation is buggy. It's a good try to fix it. However, I suspect we will always fall into this situation no matter how many threads you have.
Granted, this will just increase the number of simultaneous ASTs that can handle. But with a handling capability of 128, we may never hit the limit in practice.
I agree that a long term solution would be nice. Perhaps the server should extend ALL lock timeouts for a client that is actively canceling ANY locks. If it is making progress, then we should give it more time.
But in the short term, we set ldlm_num_threads to 128 yesterday at midday (easier than changing the version of lustre). We have not seen a single lock timeout eviction since making that change.
Today we will install my patch to fix dynamic thread creation, and I expect to see the same results.
|
|
Jinshan, if there is anything that you want to do to finalize patches 1893 and 1900, now is the time. We will be putting those in a chaos tag soon.
|
|
Sure, thanks for remind. I'd like to try patch http://review.whamcloud.com/#change,1918 because this is a production patch. It passed acceptance test but inspection is not even started. Can you please share me your patch so that I can bind them together?
|
|
Ok, I need to sanity check it first, but I'll push it up today.
It looks like 1918 replaces 1893, and then we'll need 1900 refreshed to work with 1918, correct?
|
|
I'll push a new patch for 1918 so that 1900 can be used intact.
|
|
I pushed a new patch at: http://review.whamcloud.com/#change,1918 which includes the change for growing bl thread correctly. Also, this patch can work with patch set 1 of 1900. Please take a look.
|
|
My patch is in http://review.whamcloud.com/1926
|
|
Things appear to be much, much better now. We only had two evictions over the past 2+ days.
I am uploading lu874-2012-01-09.tar.bz2.
In this log, the client handles the blocking ast
Less than three seconds later an ldlm_bl thread is able to service the new work item
But from there the trail goes quiet until the client realizes that it has been evicted, at which point it finally performs the local cancel on the lock
The lock is supposedly "already unused, calling callback". But the LDLM_CANCEL is not sent at that time. Much of the code under that patch seems to be lacking debug messages, and I am not familiar with this part of the code.
If the lock is "unused", why was it not canceled immediately?
We know that the ldlm_bl thread entered cl_lock_cancel() from the messages in the logs. I am assuming that it got there by way of:
ldlm_handle_bl_callback()
lock->l_blocking_ast(), which is osc_ldlm_blocking_ast() (from decoding the pointer from the "already unused" message)
???
cl_lock_cancel().
But note that the cl_lock_cancel is for a DIFFERENT lock.
So it seems like the client gets derailed into canceling another lock when it should really, under this situation, just send the LDLM_CANCEL for the lock it already knows is finished. Unless it can't for some reason.
That is as far as I have gotten. I don't know this area of code, so an explanation would be appreciated.
|
|
cl_lock_cancel0() is talking about the associated cl_lock, which is not the same as an ldlm_lock. This is still clear as mud beyond that though.
|
|
If the lock is unused, it means there is no process holding this lock at the client side, this lock is able to be canceled. Before canceling this lock, the client has to evict pages covered by this lock. We should write the dirty pages back and them tear down them.
I'll post my findings from this log soon.
|
|
From the client log, dlm callback process 9320 is assigned to cancel this lock. So it tried to tear down caching pages covered by this lock.
This is the 1st round, it collected all unlocked pages, that was 16128 pages in total.
Then it was blocked for a long while, I believe by a locked page, so it will await that page to be unlocked. From the log, I guess the page was at around the last 768th page of a 5632-page queue. Also, this page must have been added by page writeback thread - so it has been locked and ready for transfer. This brings us a problem: if a lock is being canceled, we should raise the priority of those pages which have already been queued by someone else.
Let's then take a look at RPC x1390296139335090 to figure out why it couldn't flush those pages in time, this RPC must be writing pages from 2816th to 2560th in the queue.
Process 4909 was assigned to handle this RPC, and there was a slow again:
|
|
Can you please try patch: http://review.whamcloud.com/#change,1938 after sanity test has passed?
|
|
Thanks!
We started running with the new patch include at noon today. Of course, evictions are now rare enough that if we see nothing, we will not really know if it helped for at least a couple of days.
|
|
We're going to start landing process because these patches make eviction less.
|
|
Integrated in  lustre-master » x86_64,server,el5,ofa #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » x86_64,client,el6,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » x86_64,client,el5,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » i686,server,el6,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » x86_64,client,sles11,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » x86_64,client,ubuntu1004,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » x86_64,server,el5,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » x86_64,client,el5,ofa #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » x86_64,server,el6,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » i686,client,el6,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » i686,server,el5,ofa #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » i686,server,el5,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » i686,client,el5,inkernel #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Integrated in lustre-master » i686,client,el5,ofa #431
LU-874 ldlm: Fix ldlm_bl_* thread creation (Revision 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5)
Result = SUCCESS
Oleg Drokin : 3551b2cc2bbb3181bbb2afc8675cb3457215f4f5
Files :
|
|
Adding this to the 2.1.1 tracker, since this has made a significant improvement on tests run with 2.1.0.
|
|
Would this commit land to b2_1 tree soon?
Thanks!
|
|
I will port it to b2_1 after landing this on master.
|
|
Hi Jinshan, I think it was landed on master on Jan 19?
Do you anticipate any logic change beyond a simple cherry-pick?
If not, I can do the cherry-pick and build.
We are eager to build a 2.1 version for testing, since LU-1065 we opened was suspected to be a dup of this bug.
|
|
there are a series of patches(4 in total) needed to solve this problem, besides that one landed the other day, you also need:
http://review.whamcloud.com/#change,1918
http://review.whamcloud.com/#change,1900
http://review.whamcloud.com/#change,1938
There is no further changes coming to these patches. I think it's pretty safe to apply them to production system since they have been using by LLNL for a while.
|
|
Hi Jinshan,
The #change.1918 caused compilation error.
You added "static inline int ldlm_res_eq" declaration to lustre_idl.h without taking
the same out from ldlm_resource.c, which includes lustre_idl.h. I ran into this error:
/tmp.chroot/nas-2.1.0-2a/lustre/ptlrpc/../../lustre/ldlm/ldlm_resource.c:423: error: redefinition of 'ldlm_res_eq'
/tmp.chroot/nas-2.1.0-2a/lustre/include/lustre/lustre_idl.h:2248: note: previous definition of 'ldlm_res_eq' was here
|
|
Please use these patches for b2_1:
http://review.whamcloud.com/2085
http://review.whamcloud.com/2086
http://review.whamcloud.com/2087
http://review.whamcloud.com/2088
|
|
Integrated in lustre-master » x86_64,server,el5,ofa #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » x86_64,client,el6,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » x86_64,client,el5,ofa #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » i686,server,el6,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » x86_64,server,el5,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » x86_64,server,el6,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » i686,client,el6,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » x86_64,client,ubuntu1004,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » i686,server,el5,ofa #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » x86_64,client,el5,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » i686,client,el5,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » x86_64,client,sles11,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » i686,server,el5,inkernel #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » i686,client,el5,ofa #453
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
Result = SUCCESS
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
|
|
Integrated in lustre-master » x86_64,client,el5,ofa #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_internal.h
- lustre/include/lustre_dlm.h
- lustre/include/lustre_net.h
- lustre/include/lustre_export.h
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_lock.c
- lustre/ost/ost_handler.c
- lustre/ptlrpc/service.c
- lustre/ldlm/ldlm_resource.c
- lustre/ldlm/ldlm_extent.c
- lustre/include/lustre/lustre_idl.h
|
|
Integrated in lustre-master » x86_64,client,el5,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/include/lustre_net.h
- lustre/ldlm/ldlm_lock.c
- lustre/include/lustre_dlm.h
- lustre/ldlm/ldlm_extent.c
- lustre/ptlrpc/service.c
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_resource.c
- lustre/ldlm/ldlm_lockd.c
- lustre/ost/ost_handler.c
- lustre/include/lustre/lustre_idl.h
- lustre/ldlm/ldlm_internal.h
- lustre/include/lustre_export.h
|
|
Integrated in lustre-master » x86_64,client,ubuntu1004,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_lock.c
- lustre/ldlm/ldlm_extent.c
- lustre/include/lustre_export.h
- lustre/ost/ost_handler.c
- lustre/ldlm/ldlm_internal.h
- lustre/include/lustre/lustre_idl.h
- lustre/include/lustre_net.h
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_resource.c
- lustre/include/lustre_dlm.h
- lustre/ptlrpc/service.c
|
|
Integrated in lustre-master » x86_64,client,sles11,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/obdclass/genops.c
- lustre/include/lustre_export.h
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_extent.c
- lustre/include/lustre_dlm.h
- lustre/ldlm/ldlm_resource.c
- lustre/include/lustre/lustre_idl.h
- lustre/ptlrpc/service.c
- lustre/ldlm/ldlm_internal.h
- lustre/include/lustre_net.h
- lustre/ost/ost_handler.c
- lustre/ldlm/ldlm_lock.c
|
|
Integrated in lustre-master » x86_64,server,el5,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/include/lustre_net.h
- lustre/include/lustre/lustre_idl.h
- lustre/ptlrpc/service.c
- lustre/ldlm/ldlm_internal.h
- lustre/ldlm/ldlm_extent.c
- lustre/ldlm/ldlm_lockd.c
- lustre/ost/ost_handler.c
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_resource.c
- lustre/include/lustre_export.h
- lustre/ldlm/ldlm_lock.c
- lustre/include/lustre_dlm.h
|
|
Integrated in lustre-master » x86_64,client,el6,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ost/ost_handler.c
- lustre/include/lustre_dlm.h
- lustre/ldlm/ldlm_resource.c
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_lock.c
- lustre/ldlm/ldlm_internal.h
- lustre/include/lustre_export.h
- lustre/include/lustre/lustre_idl.h
- lustre/ptlrpc/service.c
- lustre/ldlm/ldlm_extent.c
- lustre/include/lustre_net.h
|
|
Integrated in lustre-master » x86_64,server,el5,ofa #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ldlm/ldlm_resource.c
- lustre/ost/ost_handler.c
- lustre/ldlm/ldlm_extent.c
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_lock.c
- lustre/include/lustre_dlm.h
- lustre/include/lustre_export.h
- lustre/include/lustre/lustre_idl.h
- lustre/ptlrpc/service.c
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_internal.h
- lustre/include/lustre_net.h
|
|
Integrated in lustre-master » x86_64,server,el6,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ldlm/ldlm_lock.c
- lustre/ldlm/ldlm_extent.c
- lustre/include/lustre/lustre_idl.h
- lustre/ptlrpc/service.c
- lustre/include/lustre_dlm.h
- lustre/include/lustre_export.h
- lustre/obdclass/genops.c
- lustre/include/lustre_net.h
- lustre/ost/ost_handler.c
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_resource.c
- lustre/ldlm/ldlm_internal.h
|
|
Integrated in lustre-master » i686,client,el6,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/include/lustre/lustre_idl.h
- lustre/ldlm/ldlm_lock.c
- lustre/ptlrpc/service.c
- lustre/include/lustre_net.h
- lustre/ldlm/ldlm_internal.h
- lustre/ldlm/ldlm_extent.c
- lustre/include/lustre_export.h
- lustre/obdclass/genops.c
- lustre/ost/ost_handler.c
- lustre/ldlm/ldlm_resource.c
- lustre/ldlm/ldlm_lockd.c
- lustre/include/lustre_dlm.h
|
|
Integrated in lustre-master » i686,server,el6,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ldlm/ldlm_resource.c
- lustre/ldlm/ldlm_extent.c
- lustre/ptlrpc/service.c
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_lock.c
- lustre/include/lustre_dlm.h
- lustre/ldlm/ldlm_internal.h
- lustre/include/lustre_net.h
- lustre/include/lustre_export.h
- lustre/include/lustre/lustre_idl.h
- lustre/ost/ost_handler.c
- lustre/obdclass/genops.c
|
|
Integrated in lustre-master » i686,client,el5,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/include/lustre_export.h
- lustre/include/lustre/lustre_idl.h
- lustre/ldlm/ldlm_lock.c
- lustre/include/lustre_dlm.h
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_internal.h
- lustre/ost/ost_handler.c
- lustre/ptlrpc/service.c
- lustre/include/lustre_net.h
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_resource.c
- lustre/ldlm/ldlm_extent.c
|
|
Integrated in lustre-master » i686,server,el5,inkernel #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ldlm/ldlm_lock.c
- lustre/ldlm/ldlm_extent.c
- lustre/ldlm/ldlm_internal.h
- lustre/include/lustre_dlm.h
- lustre/ldlm/ldlm_lockd.c
- lustre/include/lustre/lustre_idl.h
- lustre/ldlm/ldlm_resource.c
- lustre/ost/ost_handler.c
- lustre/include/lustre_export.h
- lustre/include/lustre_net.h
- lustre/ptlrpc/service.c
- lustre/obdclass/genops.c
|
|
Integrated in lustre-master » i686,server,el5,ofa #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ldlm/ldlm_resource.c
- lustre/include/lustre_dlm.h
- lustre/include/lustre_net.h
- lustre/ptlrpc/service.c
- lustre/include/lustre_export.h
- lustre/ldlm/ldlm_internal.h
- lustre/ldlm/ldlm_lockd.c
- lustre/ost/ost_handler.c
- lustre/include/lustre/lustre_idl.h
- lustre/ldlm/ldlm_extent.c
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_lock.c
|
|
Integrated in lustre-master » i686,client,el5,ofa #468
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = SUCCESS
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ldlm/ldlm_resource.c
- lustre/ldlm/ldlm_lock.c
- lustre/ldlm/ldlm_internal.h
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_extent.c
- lustre/ptlrpc/service.c
- lustre/obdclass/genops.c
- lustre/include/lustre_dlm.h
- lustre/include/lustre/lustre_idl.h
- lustre/ost/ost_handler.c
- lustre/include/lustre_net.h
- lustre/include/lustre_export.h
|
|
All patches landed for 2.2
|
|
We are pretty sure we are encountering this problem on one of our clusters right now, and it's causing a lot of user pain.
Have the patches posted by Jinshan Xiong on 03/Feb made it into b2_1 yet, or should they be applied directly? Should these patches be considered production-ready, or are they unstable enough that we should wait for a release?
We'd really like to get rid of this issue asap, but obviously if the patches are still considered unstable we should wait...
|
|
I think they are pretty safe to be applied to production system.
|
|
If you apply the commit 15bd23 to b2_1 tree, you will fail in compilation for the reason I stated in the comment on 03/Feb/12 1:30 PM.
|
|
patches for b2_1 are at:
Jinshan Xiong added a comment - 03/Feb/12 3:45 PM
Please use these patches for b2_1:
http://review.whamcloud.com/2085
http://review.whamcloud.com/2086
http://review.whamcloud.com/2087
http://review.whamcloud.com/2088
|
|
Hi,
Are the patches for b2_1 ready for production ? I see there are two patches (http://review.whamcloud.com/#change,2086 and http://review.whamcloud.com/#change,2087) with still some failed tests on Maloo.
|
|
Integrated in  lustre-master » x86_64,server,el6,ofa #480
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = FAILURE
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ldlm/ldlm_resource.c
- lustre/include/lustre_export.h
- lustre/ldlm/ldlm_internal.h
- lustre/ldlm/ldlm_extent.c
- lustre/include/lustre_net.h
- lustre/include/lustre/lustre_idl.h
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_lock.c
- lustre/ptlrpc/service.c
- lustre/ost/ost_handler.c
- lustre/ldlm/ldlm_lockd.c
- lustre/include/lustre_dlm.h
|
|
Integrated in lustre-master » x86_64,client,el6,ofa #480
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = FAILURE
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/ldlm/ldlm_resource.c
- lustre/ldlm/ldlm_internal.h
- lustre/ost/ost_handler.c
- lustre/include/lustre_net.h
- lustre/ptlrpc/service.c
- lustre/ldlm/ldlm_lock.c
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_lockd.c
- lustre/ldlm/ldlm_extent.c
- lustre/include/lustre_export.h
- lustre/include/lustre_dlm.h
- lustre/include/lustre/lustre_idl.h
|
|
Integrated in  lustre-master » i686,client,el6,ofa #480
LU-874 ldlm: prioritize LDLM_CANCEL requests (Revision 58f98d4c4477f16557b54162a9566ac38a0fef38)
LU-874 osc: prioritize writeback pages (Revision 26de7f886db3724bf6af307c9863e2d723b88b68)
LU-874 ptlrpc: handle in-flight hqreq correctly (Revision 15bd23c47332e476b985b220170fd47814ab7f14)
Result = ABORTED
Oleg Drokin : 58f98d4c4477f16557b54162a9566ac38a0fef38
Files :
Oleg Drokin : 26de7f886db3724bf6af307c9863e2d723b88b68
Files :
Oleg Drokin : 15bd23c47332e476b985b220170fd47814ab7f14
Files :
- lustre/include/lustre_net.h
- lustre/ldlm/ldlm_lockd.c
- lustre/include/lustre_export.h
- lustre/include/lustre/lustre_idl.h
- lustre/obdclass/genops.c
- lustre/ldlm/ldlm_lock.c
- lustre/ldlm/ldlm_internal.h
- lustre/ptlrpc/service.c
- lustre/ost/ost_handler.c
- lustre/ldlm/ldlm_extent.c
- lustre/ldlm/ldlm_resource.c
- lustre/include/lustre_dlm.h
|
|
Hi,
During testing at CEA, we hit a new occurrence of this issue. The bad news is that the test cluster is running Lustre 2.1.2, which already contains the 4 patches from this defect.
Here is what we see with crash:
crash> ps | grep -v " IN "
PID PPID CPU TASK ST %MEM VSZ RSS COMM
0 0 0 ffffffff81a0e020 RU 0.0 0 0 [swapper]
> 0 0 1 ffff88063e4ee040 RU 0.0 0 0 [swapper]
> 0 0 2 ffff88063e4ee790 RU 0.0 0 0 [swapper]
> 0 0 3 ffff88063e4f6080 RU 0.0 0 0 [swapper]
> 0 0 4 ffff88063e4f67d0 RU 0.0 0 0 [swapper]
> 0 0 5 ffff88063e5770c0 RU 0.0 0 0 [swapper]
> 0 0 6 ffff88063e577810 RU 0.0 0 0 [swapper]
> 0 0 7 ffff88063e5df100 RU 0.0 0 0 [swapper]
10244 10238 4 ffff88033b91a850 UN 0.1 1193576 15348 reproducer
10247 10243 0 ffff88033c167080 ?? 0.0 0 0 reproducer
10248 10244 4 ffff88063d1eb850 ?? 0.0 0 0 reproducer
16196 2 5 ffff88063c98a0c0 UN 0.0 0 0 [ptlrpcd_7]
> 22688 22622 0 ffff88063c95c100 RU 0.6 278972 147600 crash
22697 22688 5 ffff88033b94a790 RU 0.0 105288 884 grep
crash> ps | grep reproducer
10243 10238 0 ffff88033c04b080 IN 0.1 1193604 15420 reproducer
10244 10238 4 ffff88033b91a850 UN 0.1 1193576 15348 reproducer
10247 10243 0 ffff88033c167080 ?? 0.0 0 0 reproducer
10248 10244 4 ffff88063d1eb850 ?? 0.0 0 0 reproducer
crash> bt 10243
PID: 10243 TASK: ffff88033c04b080 CPU: 0 COMMAND: "reproducer"
#0 [ffff88030dfab7e8] schedule at ffffffff81484c15
#1 [ffff88030dfab8b0] cfs_waitq_wait at ffffffffa040e74e [libcfs]
#2 [ffff88030dfab8c0] cl_sync_io_wait at ffffffffa053285b [obdclass]
#3 [ffff88030dfab960] cl_io_submit_sync at ffffffffa0532ad3 [obdclass]
#4 [ffff88030dfab9c0] cl_lock_page_out at ffffffffa0529ae7 [obdclass]
#5 [ffff88030dfaba30] osc_lock_flush at ffffffffa091c75f [osc]
#6 [ffff88030dfaba80] osc_lock_cancel at ffffffffa091c7f9 [osc]
#7 [ffff88030dfabad0] cl_lock_cancel0 at ffffffffa05286c5 [obdclass]
#8 [ffff88030dfabb00] cl_lock_hold_release at ffffffffa052a446 [obdclass]
#9 [ffff88030dfabb20] cl_lock_unhold at ffffffffa052c187 [obdclass]
#10 [ffff88030dfabb50] lov_sublock_release at ffffffffa0998ca8 [lov]
#11 [ffff88030dfabba0] lov_lock_enqueue at ffffffffa099b242 [lov]
#12 [ffff88030dfabc30] cl_enqueue_try at ffffffffa052cc6c [obdclass]
#13 [ffff88030dfabc80] cl_enqueue_locked at ffffffffa052e06d [obdclass]
#14 [ffff88030dfabcc0] cl_lock_request at ffffffffa052ecee [obdclass]
#15 [ffff88030dfabd20] cl_glimpse_lock at ffffffffa0a737cf [lustre]
#16 [ffff88030dfabd80] cl_glimpse_size at ffffffffa0a73f94 [lustre]
#17 [ffff88030dfabdd0] ll_inode_revalidate_it at ffffffffa0a376de [lustre]
#18 [ffff88030dfabe10] ll_getattr_it at ffffffffa0a37839 [lustre]
#19 [ffff88030dfabe40] ll_getattr at ffffffffa0a37997 [lustre]
#20 [ffff88030dfabe80] vfs_getattr at ffffffff811684c1
#21 [ffff88030dfabec0] vfs_fstat at ffffffff8116877f
#22 [ffff88030dfabef0] sys_newfstat at ffffffff811687c4
#23 [ffff88030dfabf80] system_call_fastpath at ffffffff810030f2
RIP: 00007f4b46e97334 RSP: 00007fff3e6e63d0 RFLAGS: 00000202
RAX: 0000000000000005 RBX: ffffffff810030f2 RCX: 00007f4b46e8c177
RDX: 00007fff3e6e6580 RSI: 00007fff3e6e6580 RDI: 000000000000001c
RBP: 00007fff3e6e6740 R8: 000000000000000c R9: 0000000000000006
R10: 0000000000000005 R11: 0000000000000246 R12: 000000000000001c
R13: 0000000000000010 R14: 0000000000000010 R15: 0000000000000001
ORIG_RAX: 0000000000000005 CS: 0033 SS: 002b
crash> bt 10244
PID: 10244 TASK: ffff88033b91a850 CPU: 4 COMMAND: "reproducer"
#0 [ffff8803063d7938] schedule at ffffffff81484c15
#1 [ffff8803063d7a00] __mutex_lock_slowpath at ffffffff814862ce
#2 [ffff8803063d7a80] mutex_lock at ffffffff8148615b
#3 [ffff8803063d7aa0] cl_lock_mutex_get at ffffffffa052aeb7 [obdclass]
#4 [ffff8803063d7ad0] cl_lock_state_wait at ffffffffa052d92d [obdclass]
#5 [ffff8803063d7b50] cl_lock_enqueue_wait at ffffffffa052dde5 [obdclass]
#6 [ffff8803063d7b90] lov_lock_enqueue at ffffffffa099b4df [lov]
#7 [ffff8803063d7c20] cl_enqueue_try at ffffffffa052cc6c [obdclass]
#8 [ffff8803063d7c70] cl_enqueue_locked at ffffffffa052e06d [obdclass]
#9 [ffff8803063d7cb0] cl_lock_request at ffffffffa052ecee [obdclass]
#10 [ffff8803063d7d10] cl_io_lock at ffffffffa0534035 [obdclass]
#11 [ffff8803063d7d70] cl_io_loop at ffffffffa053428a [obdclass]
#12 [ffff8803063d7db0] ll_file_io_generic at ffffffffa0a2cf0b [lustre]
#13 [ffff8803063d7e20] ll_file_aio_write at ffffffffa0a2d8ac [lustre]
#14 [ffff8803063d7e80] ll_file_write at ffffffffa0a2db99 [lustre]
#15 [ffff8803063d7ef0] vfs_write at ffffffff811631d8
#16 [ffff8803063d7f30] sys_write at ffffffff81163be1
#17 [ffff8803063d7f80] system_call_fastpath at ffffffff810030f2
RIP: 00007fa865a3848d RSP: 00007fff08ff8e38 RFLAGS: 00000202
RAX: 0000000000000001 RBX: ffffffff810030f2 RCX: 00000000003dfb00
RDX: 0000000000118bc0 RSI: 00007fa81dead010 RDI: 000000000000001c
RBP: 00007fff08ff92a0 R8: 000000000000000c R9: 0000000000000006
R10: 0000000000000005 R11: 0000000000000293 R12: 0000000000000002
R13: 000000000000001c R14: 0000000000000010 R15: 0000000000000001
ORIG_RAX: 0000000000000001 CS: 0033 SS: 002b
crash> bt 16196
PID: 16196 TASK: ffff88063c98a0c0 CPU: 4 COMMAND: "ptlrpcd_7"
#0 [ffff88062ad139b0] schedule at ffffffff81484c15
#1 [ffff88062ad13a78] __mutex_lock_slowpath at ffffffff814862ce
#2 [ffff88062ad13af8] mutex_lock at ffffffff8148615b
#3 [ffff88062ad13b18] cl_lock_mutex_get at ffffffffa052aeb7 [obdclass]
#4 [ffff88062ad13b48] lovsub_parent_lock at ffffffffa09a2db9 [lov]
#5 [ffff88062ad13b68] lovsub_lock_state at ffffffffa09a3549 [lov]
#6 [ffff88062ad13bb8] cl_lock_state_signal at ffffffffa0529de8 [obdclass]
#7 [ffff88062ad13bf8] cl_lock_signal at ffffffffa052aa3a [obdclass]
#8 [ffff88062ad13c18] osc_lock_upcall at ffffffffa091e23a [osc]
#9 [ffff88062ad13c88] osc_enqueue_fini at ffffffffa0901d9e [osc]
#10 [ffff88062ad13cd8] osc_enqueue_interpret at ffffffffa0907b4e [osc]
#11 [ffff88062ad13d58] ptlrpc_check_set at ffffffffa066c103 [ptlrpc]
#12 [ffff88062ad13e08] ptlrpcd_check at ffffffffa069f563 [ptlrpc]
#13 [ffff88062ad13e68] ptlrpcd at ffffffffa069fe14 [ptlrpc]
#14 [ffff88062ad13f48] kernel_thread at ffffffff8100412a
crash>
The dmesg on the server is:
Lustre: DEBUG MARKER: Fri Sep 28 09:50:01 2012
LustreError: 0:0:(ldlm_lockd.c:358:waiting_locks_callback()) ### lock callback timer expired after 100s: evicting client
at JO.BOB.BAL.TT@o2ib1 ns: filter-ptmp-OST000e_UUID lock: ffff880374d15b40/0x7a81ca8fd961bfdc lrc: 3/0,0 mode: PW/PW
res: 317407/0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->184319) flags: 0x20 remote: 0x2f886f4ac30e736c
expref: 4 pid: 12527 timeout 4502547463
Lustre: 12634:0:(ldlm_lib.c:947:target_handle_connect()) ptmp-OST000e: connection from
1eb0bec5-18e1-c608-250f-9a0d61bd565f@JO.BOB.BAL.TT@o2ib1 t0 exp (null) cur 1348818719 last 0
Lustre: DEBUG MARKER: Fri Sep 28 09:55:01 2012
Lustre: ptmp-OST000e: haven't heard from client 1eb0bec5-18e1-c608-250f-9a0d61bd565f (at JO.BOB.BAL.TT@o2ib1) in 227
seconds. I think it's dead, and I am evicting it. exp ffff88012f5ef800, cur 1348818946 expire 1348818796 last 1348818719
Lustre: Skipped 11 previous similar messages
Lustre: DEBUG MARKER: Fri Sep 28 10:00:01 2012
And on the client, the dmesg contains:
Lustre: DEBUG MARKER: Fri Sep 28 09:50:01 2012
LustreError: 11-0: an error occurred while communicating with JO.BOB.BAO.AL@o2ib1. The obd_ping operation failed with
-107
Lustre: ptmp-OST000e-osc-ffff88063b447000: Connection to ptmp-OST000e (at JO.BOB.BAO.AL@o2ib1) was lost; in progress
operations using this service will wait for recovery to complete
LustreError: 167-0: This client was evicted by ptmp-OST000e; in progress operations using this service will fail.
LustreError: 481:0:(import.c:326:ptlrpc_invalidate_import()) ptmp-OST000e_UUID: rc = -110 waiting for callback (1 != 0)
LustreError: 481:0:(import.c:352:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff88032f14c400
x1414088799797679/t0(0) o4->ptmp-OST000e-osc-ffff88063b447000@JO.BOB.BAO.AL@o2ib1:6/4 lens 456/416 e 0 to 0 dl 1348818633
ref 2 fl Rpc:RE/0/ffffffff rc -4/-1
LustreError: 481:0:(import.c:368:ptlrpc_invalidate_import()) ptmp-OST000e_UUID: RPCs in "Unregistering" phase
found (0). Network is sluggish? Waiting them to error out.
Lustre: DEBUG MARKER: Fri Sep 28 09:55:01 2012
LustreError: 481:0:(import.c:326:ptlrpc_invalidate_import()) ptmp-OST000e_UUID: rc = -110 waiting for callback (1 != 0)
LustreError: 481:0:(import.c:352:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff88032f14c400
x1414088799797679/t0(0) o4->ptmp-OST000e-osc-ffff88063b447000@JO.BOB.BAO.AL@o2ib1:6/4 lens 456/416 e 0 to 0 dl 1348818633
ref 2 fl Rpc:RE/0/ffffffff rc -4/-1
LustreError: 481:0:(import.c:368:ptlrpc_invalidate_import()) ptmp-OST000e_UUID: RPCs in "Unregistering" phase
found (0). Network is sluggish? Waiting them to error out.
But the good news is that we now have a reproducer. I will attach it in my next comment.
Sebastien.
|
|
Here is the reproducer used at CEA. The issue is quite easy to reproduce if the stripe count is 2.
To run the test:
$ mpicc -o reproducer reproducer.c
$ rm test.bin ; lfs setstripe -c 2 ./test.bin
$ srun --exclusive --resv-ports -n 4 -N 2-2 -p testing /dir/read_write/reproducer
Please note that if we remove the fstat() system call from the reproducer, the issue cannot be reproduced anymore.
I hope all this information will help you investigate this issue.
TIA,
Sebastien.
|
|
Hi Sebastien,
Do you have patch a02dbe9d1b14ee67c2982f83804f9baffca59c04(LU-1274) applied in your branch?
|
|
Hi Jinshan,
The patch you are pointing to was merged just before 2.1.2-RC1, so yes it is included in our sources.
Sebastien.
|
|
Bobijam
Could you please investigate the latest information supplied on this ticket
Thanks
Peter
|
|
Xiong,
From the backtrace of thread 10244 (reproducer) and 14196 (ptlrpcd), they were all running on CPU 4
For thread 10244, it is a write operation trying to enqueue a lovsub lock, and waiting for an exist conflicting lovsub lock to cancel pages it covers.
when it comes to lov_lock_enqueue_wait() it has lov lock mutexed, and when it comes to cl_lock_enqueue_wait() it has the conflicting lovsub lock's mutexed. (parent mutex get, then child mutex get)
As for thread 14196, ptlrpcd finished an osc lock enqueue handling, calling osc_lock_upcall() to notify top locks, it has lovsub lock's mutexed, when the calling path go through cl_lock_state_signal()->lovsub_lock_state(), it try to get lov lock's mutex. (child mutex get, then parent mutex get)
Xiong, does it sound a dead lock here?
|
|
Hi Bobi, yes this is a deadlock case, we should release parent lock before waiting for the conflict lock.
|
|
master patch tracking at http://review.whamcloud.com/4306
LU-874 clio: avoid cl_lock deadlock
We should not get cl_lock mutexes from top to bottom directly, could
possibly cause a dead lock.
See comments above cl_lock::cll_guard.
|
|
After taking a closer look, I think this issue is more about getting stuck at page flush. See process 10243:
crash> bt 10243
PID: 10243 TASK: ffff88033c04b080 CPU: 0 COMMAND: "reproducer"
#0 [ffff88030dfab7e8] schedule at ffffffff81484c15
#1 [ffff88030dfab8b0] cfs_waitq_wait at ffffffffa040e74e [libcfs]
#2 [ffff88030dfab8c0] cl_sync_io_wait at ffffffffa053285b [obdclass]
#3 [ffff88030dfab960] cl_io_submit_sync at ffffffffa0532ad3 [obdclass]
#4 [ffff88030dfab9c0] cl_lock_page_out at ffffffffa0529ae7 [obdclass]
#5 [ffff88030dfaba30] osc_lock_flush at ffffffffa091c75f [osc]
#6 [ffff88030dfaba80] osc_lock_cancel at ffffffffa091c7f9 [osc]
#7 [ffff88030dfabad0] cl_lock_cancel0 at ffffffffa05286c5 [obdclass]
#8 [ffff88030dfabb00] cl_lock_hold_release at ffffffffa052a446 [obdclass]
it was waiting for the write to finish while holding mutex of cl_lock. This is why you can see other processes were blocking at cl_lock mutex.
Then, when the client was evicted, the write request was still in the sending list, that means it didn't receive the reply from OST yet.
LustreError: 11-0: an error occurred while communicating with JO.BOB.BAO.AL@o2ib1. The obd_ping operation failed with
-107
Lustre: ptmp-OST000e-osc-ffff88063b447000: Connection to ptmp-OST000e (at JO.BOB.BAO.AL@o2ib1) was lost; in progress
operations using this service will wait for recovery to complete
LustreError: 167-0: This client was evicted by ptmp-OST000e; in progress operations using this service will fail.
LustreError: 481:0:(import.c:326:ptlrpc_invalidate_import()) ptmp-OST000e_UUID: rc = -110 waiting for callback (1 != 0)
LustreError: 481:0:(import.c:352:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff88032f14c400
x1414088799797679/t0(0) o4->ptmp-OST000e-osc-ffff88063b447000@JO.BOB.BAO.AL@o2ib1:6/4 lens 456/416 e 0 to 0 dl 1348818633
ref 2 fl Rpc:RE/0/ffffffff rc -4/-1
LustreError: 481:0:(import.c:368:ptlrpc_invalidate_import()) ptmp-OST000e_UUID: RPCs in "Unregistering" phase
found (0). Network is sluggish? Waiting them to error out.
Can you please take a look at OST log to check if there is any information about the RPC x1414088799797679? If the patches work, this request should be put into high prio RPC list, and lock's expiration timeout should be renewed.
|
|
Hi Sebastien Buisson, can you please rerun the test and collect and provide us log, thanks in advance.
|
|
Jinshan, the patch on http://review.whamcloud.com/#change,4306 hasn't yet been approved. Despite that do you think it's safe to give it a try in production?
|
|
Please don't try that one. I just want to understand the problem better.
|
|
Hi,
All available logs from the OST were given on October, 1st (server dmesg). And unfortunately, there is no mention of the RPC x1414088799797679.
I think you can try to rerun the reproducer by yourself if you need information that our logs lack.
Cheers,
Sebastien.
|
|
Jinshan,
I have been able to reproduce it on Toro with reproducer.c and a very small test-platform :
_ 1 node acting as a 1xMDS + 2xOSSs + 1xClient running one of the latest Lustre-2.1 build (courtesy from Johann)
_ 1 other node acting as a simple Client running one of the latest Lustre-2.3 build (again courtesy from Johann, in fact I hacked his node ...)
_ OpenMPI with simple rsh+TCP/Eth transport/interface.
The Lustre-2.3 stack (taken via Alt+SysRq+T) is just a little bit different at the end/top (after osc_lock_flush() call) due to Client write-cache feature, I assume ... :
===============================================================================================
Nov 27 01:09:17 client-15 kernel: reproducer S 0000000000000001 0 8231 1 0x00000080
Nov 27 01:09:17 client-15 kernel: ffff8802e399d538 0000000000000082 ffff8802e399d538 ffffffff814fea8a
Nov 27 01:09:17 client-15 kernel: ffff8802e399d4b8 0000000000000286 000000000000001c 00000000000000ff
Nov 27 01:09:17 client-15 kernel: ffff88032f0e3af8 ffff8802e399dfd8 000000000000fb88 ffff88032f0e3af8
Nov 27 01:09:17 client-15 kernel: Call Trace:
Nov 27 01:09:17 client-15 kernel: [<ffffffff814fea8a>] ? schedule_timeout+0x19a/0x2e0
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0e0d77e>] cfs_waitq_wait+0xe/0x10 [libcfs]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa05f6d27>] osc_extent_wait+0x5f7/0x6c0 [osc]
Nov 27 01:09:17 client-15 kernel: [<ffffffff81060250>] ? default_wake_function+0x0/0x20
Nov 27 01:09:17 client-15 kernel: [<ffffffffa05f714c>] osc_cache_wait_range+0x35c/0x9a0 [osc]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0f85a3e>] ? cl_object_put+0xe/0x10 [obdclass]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa05f38b8>] ? osc_io_unplug0+0x748/0x12a0 [osc]
Nov 27 01:09:17 client-15 kernel: [<ffffffff8127ce66>] ? vsnprintf+0x2b6/0x5f0
Nov 27 01:09:17 client-15 kernel: [<ffffffffa05fc731>] osc_cache_writeback_range+0xd61/0x1160 [osc]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0e0c27b>] ? cfs_set_ptldebug_header+0x2b/0xc0 [libcfs]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0e22d97>] ? cfs_hash_bd_lookup_intent+0x37/0x130 [libcfs]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0e222d2>] ? cfs_hash_bd_add_locked+0x62/0x90 [libcfs]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0f8709d>] ? cl_env_nested_get+0x5d/0xc0 [obdclass]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0e25cbb>] ? cfs_hash_add_unique+0x1b/0x40 [libcfs]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa05e40f6>] osc_lock_flush+0x86/0x200 [osc]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa05e4357>] osc_lock_cancel+0xe7/0x1c0 [osc]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0f8d0a5>] cl_lock_cancel0+0x75/0x160 [obdclass]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0f8ece6>] cl_lock_hold_release+0x1c6/0x2b0 [obdclass]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0f90837>] cl_lock_unhold+0x37/0x130 [obdclass]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa067e5f8>] lov_sublock_release+0x1a8/0x2a0 [lov]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa06811fb>] lov_lock_enqueue+0x2cb/0x830 [lov]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0f9149c>] cl_enqueue_try+0xfc/0x310 [obdclass]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0f9295d>] cl_enqueue_locked+0x6d/0x210 [obdclass]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0f9363e>] cl_lock_request+0x7e/0x280 [obdclass]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0be3deb>] cl_glimpse_lock+0x17b/0x4a0 [lustre]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0be4677>] cl_glimpse_size0+0x187/0x190 [lustre]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0ba0ee2>] ll_inode_revalidate_it+0xf2/0x1c0 [lustre]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0e22134>] ? cfs_hash_dual_bd_unlock+0x34/0x60 [libcfs]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0ba0ff9>] ll_getattr_it+0x49/0x170 [lustre]
Nov 27 01:09:17 client-15 kernel: [<ffffffffa0ba1157>] ll_getattr+0x37/0x40 [lustre]
Nov 27 01:09:17 client-15 kernel: [<ffffffff812143d3>] ? security_inode_getattr+0x23/0x30
Nov 27 01:09:17 client-15 kernel: [<ffffffff81180571>] vfs_getattr+0x51/0x80
Nov 27 01:09:17 client-15 kernel: [<ffffffff8118082f>] vfs_fstat+0x3f/0x60
Nov 27 01:09:17 client-15 kernel: [<ffffffff81180874>] sys_newfstat+0x24/0x40
Nov 27 01:09:17 client-15 kernel: [<ffffffff810d6b12>] ? audit_syscall_entry+0x272/0x2a0
Nov 27 01:09:17 client-15 kernel: [<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b
===============================================================================================
So the run/task is stuck for ever and when we try to reboot the Lustre-2.3 Node/Client we get :
===============================================================================================
LustreError: 8231:0:(cl_lock.c:1960:discard_cb()) ASSERTION( (!(page->cp_type == CPT_CACHEABLE) || (!PageWriteback(cl_page_vmpage(env, page)))) ) failed:
LustreError: 8231:0:(cl_lock.c:1960:discard_cb()) LBUG
[ OK Pid: 8231, comm: reproducer
Call Trace:
[<ffffffffa0e0c905>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
[<ffffffffa0e0cf17>] lbug_with_loc+0x47/0xb0 [libcfs]
[<ffffffffa0f8f66c>] discard_cb+0x1ec/0x1f0 [obdclass]
[<ffffffffa0f8c864>] cl_page_gang_lookup+0x1f4/0x400 [obdclass]
[<ffffffffa0f8f480>] ? discard_cb+0x0/0x1f0 [obdclass]
[<ffffffffa0f8f480>] ? discard_cb+0x0/0x1f0 [obdclass]
[<ffffffffa0f8f33e>] cl_lock_discard_pages+0x11e/0x1f0 [obdclass]
[<ffffffffa05e4180>] osc_lock_flush+0x110/0x200 [osc]
[<ffffffffa05e4357>] osc_lock_cancel+0xe7/0x1c0 [osc]
[<ffffffffa0f8d0a5>] cl_lock_cancel0+0x75/0x160 [obdclass]
[<ffffffffa0f8ece6>] cl_lock_hold_release+0x1c6/0x2b0 [obdclass]
[<ffffffffa0f90837>] cl_lock_unhold+0x37/0x130 [obdclass]
[<ffffffffa067e5f8>] lov_sublock_release+0x1a8/0x2a0 [lov]
[<ffffffffa06811fb>] lov_lock_enqueue+0x2cb/0x830 [lov]
[<ffffffffa0f9149c>] cl_enqueue_try+0xfc/0x310 [obdclass]
[<ffffffffa0f9295d>] cl_enqueue_locked+0x6d/0x210 [obdclass]
[<ffffffffa0f9363e>] cl_lock_request+0x7e/0x280 [obdclass]
[<ffffffffa0be3deb>] cl_glimpse_lock+0x17b/0x4a0 [lustre]
[<ffffffffa0be4677>] cl_glimpse_size0+0x187/0x190 [lustre]
[<ffffffffa0ba0ee2>] ll_inode_revalidate_it+0xf2/0x1c0 [lustre]
[<ffffffffa0e22134>] ? cfs_hash_dual_bd_unlock+0x34/0x60 [libcfs]
[<ffffffffa0ba0ff9>] ll_getattr_it+0x49/0x170 [lustre]
[<ffffffffa0ba1157>] ll_getattr+0x37/0x40 [lustre]
[<ffffffff812143d3>] ? security_inode_getattr+0x23/0x30
[<ffffffff81180571>] vfs_getattr+0x51/0x80
[<ffffffff8118082f>] vfs_fstat+0x3f/0x60
[<ffffffff81180874>] sys_newfstat+0x24/0x40
[<ffffffff810d6b12>] ? audit_syscall_entry+0x272/0x2a0
[<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b
Kernel panic - not syncing: LBUG
Pid: 8231, comm: reproducer Tainted: P --------------- 2.6.32-279.5.1.el6_lustre.g8e452a9.x86_64 #1
Call Trace:
[<ffffffff814fd57a>] ? panic+0xa0/0x168
[<ffffffffa0e0cf6b>] ? lbug_with_loc+0x9b/0xb0 [libcfs]
[<ffffffffa0f8f66c>] ? discard_cb+0x1ec/0x1f0 [obdclass]
[<ffffffffa0f8c864>] ? cl_page_gang_lookup+0x1f4/0x400 [obdclass]
[<ffffffffa0f8f480>] ? discard_cb+0x0/0x1f0 [obdclass]
[<ffffffffa0f8f480>] ? discard_cb+0x0/0x1f0 [obdclass]
[<ffffffffa0f8f33e>] ? cl_lock_discard_pages+0x11e/0x1f0 [obdclass]
[<ffffffffa05e4180>] ? osc_lock_flush+0x110/0x200 [osc]
[<ffffffffa05e4357>] ? osc_lock_cancel+0xe7/0x1c0 [osc]
[<ffffffffa0f8d0a5>] ? cl_lock_cancel0+0x75/0x160 [obdclass]
[<ffffffffa0f8ece6>] ? cl_lock_hold_release+0x1c6/0x2b0 [obdclass]
[<ffffffffa0f90837>] ? cl_lock_unhold+0x37/0x130 [obdclass]
[<ffffffffa067e5f8>] ? lov_sublock_release+0x1a8/0x2a0 [lov]
[<ffffffffa06811fb>] ? lov_lock_enqueue+0x2cb/0x830 [lov]
[<ffffffffa0f9149c>] ? cl_enqueue_try+0xfc/0x310 [obdclass]
[<ffffffffa0f9295d>] ? cl_enqueue_locked+0x6d/0x210 [obdclass]
[<ffffffffa0f9363e>] ? cl_lock_request+0x7e/0x280 [obdclass]
[<ffffffffa0be3deb>] ? cl_glimpse_lock+0x17b/0x4a0 [lustre]
[<ffffffffa0be4677>] ? cl_glimpse_size0+0x187/0x190 [lustre]
[<ffffffffa0ba0ee2>] ? ll_inode_revalidate_it+0xf2/0x1c0 [lustre]
[<ffffffffa0e22134>] ? cfs_hash_dual_bd_unlock+0x34/0x60 [libcfs]
[<ffffffffa0ba0ff9>] ? ll_getattr_it+0x49/0x170 [lustre]
[<ffffffffa0ba1157>] ? ll_getattr+0x37/0x40 [lustre]
[<ffffffff812143d3>] ? security_inode_getattr+0x23/0x30
[<ffffffff81180571>] ? vfs_getattr+0x51/0x80
[<ffffffff8118082f>] ? vfs_fstat+0x3f/0x60
[<ffffffff81180874>] ? sys_newfstat+0x24/0x40
[<ffffffff810d6b12>] ? audit_syscall_entry+0x272/0x2a0
[<ffffffff8100b0f2>] ? system_call_fastpath+0x16/0x1b
===============================================================================================
When this occurs we can find the same messages sequence in Client syslog ... But reproducer does not work very solid in such configuration, so I will try to confirm/reproduce with a full Lustre-2.1 config.
Will let you know.
Bruno.
|
|
Humm forget my earlier 2nd part comments about the LBUG upon restart "(cl_lock.c:1960:discard_cb()) ASSERTION( (!(page->cp_type == CPT_CACHEABLE) || (!PageWriteback(cl_page_vmpage(env, page)))) ) failed", I think I triggered it due to using a Client running with a Lustre-2.3 build from Johann and for LU-1680 which adresses this particular LBUG !!!
|
|
Hi Bruno, the hang at osc_extent_wait() should have been fixed with patches: 300526627be80c16be05dd1abd9a05b563dc0763 of LU-2286 and patch 4659. Can you please give them a try?
|
|
Hello Jinshan,
Sorry for the delay to answer you.
Both patches you pointed (300526627be80c16be05dd1abd9a05b563dc0763 of LU-2286 and patch 4659) are against Master, do they have b2_1 versions/ports ?? I may also try to build + run again with a 2.3 Client version, and thus do you know of a build in lustre-reviews I can boot on Toro and sure to contain both patches ??
Or do I need finally to build my own Lustre distro after integrating/poring the patches??
Thank's again+in advance for your help.
Bye.
Bruno.
|
|
And BTW, I just went to Toro see how worked my current reproducer session and I discovered it triggered after more than a full day running the reproducer with the following configuration :
_ client-17 as the Server for MDT+2xOSTs (v2.1 lustre-reviews build 10648)
_ 5x Clients client-12vm[1-4] (v2.2.96), client-15 (v2.1 lustre-reviews build 10648)
_ OpenMPI again with simple rsh+TCP/Eth transport/interface, and 3 tasks runnin on each of the 5 Clients.
And again the same situation/stack and msgs on concerned Client:
================================================================
.....
LustreError: 24977:0:(import.c:366:ptlrpc_invalidate_import()) lustre-OST0001_UUID: RPCs in "Unregistering" phase found (0). Network is sluggish? Waiting them to error out.
LustreError: 24977:0:(import.c:366:ptlrpc_invalidate_import()) Skipped 29 previous similar messages
LustreError: 24977:0:(import.c:324:ptlrpc_invalidate_import()) lustre-OST0001_UUID: rc = -110 waiting for callback (1 != 0)
LustreError: 24977:0:(import.c:324:ptlrpc_invalidate_import()) Skipped 29 previous similar messages
LustreError: 24977:0:(import.c:350:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff880052666c00 x1419903753935863/t0(0) o4->lustre-OST0001-osc-ffff880073039c00@10.10.4.17@tcp:6/4 lens 488/448 e 0 to 0 dl 1354194226 ref 2 fl Rpc:RE/0/ffffffff rc -5/-1
LustreError: 24977:0:(import.c:350:ptlrpc_invalidate_import()) Skipped 29 previous similar messages
.....
reproducer S 0000000000000000 0 24964 24962 0x00000080
ffff88003f3cb608 0000000000000086 ffff88003f3cb578 ffffffffa074c2ac
ffff88003f3cb588 0000000000000025 0000000000000000 ffff88007bd4c780
ffff88006fc40638 ffff88003f3cbfd8 000000000000fb88 ffff88006fc40638
Call Trace:
[<ffffffffa074c2ac>] ? lustre_msg_get_opc+0x9c/0x110 [ptlrpc]
[<ffffffffa0f4477e>] cfs_waitq_wait+0xe/0x10 [libcfs]
[<ffffffffa091b13f>] osc_extent_wait+0xef/0x2a0 [osc]
[<ffffffff81060250>] ? default_wake_function+0x0/0x20
[<ffffffffa091b64c>] osc_cache_wait_range+0x35c/0x9a0 [osc]
[<ffffffffa05e496e>] ? cl_object_put+0xe/0x10 [obdclass]
[<ffffffffa0918d78>] ? osc_io_unplug0+0x748/0x12a0 [osc]
[<ffffffffa09208e1>] osc_cache_writeback_range+0xd71/0x1180 [osc]
[<ffffffff81060262>] ? default_wake_function+0x12/0x20
[<ffffffffa0f59db7>] ? cfs_hash_bd_lookup_intent+0x37/0x130 [libcfs]
[<ffffffffa0f592f2>] ? cfs_hash_bd_add_locked+0x62/0x90 [libcfs]
[<ffffffffa05e5fcd>] ? cl_env_nested_get+0x5d/0xc0 [obdclass]
[<ffffffffa0f5ccdb>] ? cfs_hash_add_unique+0x1b/0x40 [libcfs]
[<ffffffffa09084d6>] osc_lock_flush+0x86/0x200 [osc]
[<ffffffffa09086a9>] osc_lock_cancel+0x59/0x1a0 [osc]
[<ffffffffa05ebf95>] cl_lock_cancel0+0x75/0x160 [obdclass]
[<ffffffffa05edbd6>] cl_lock_hold_release+0x1c6/0x2b0 [obdclass]
[<ffffffffa05ef727>] cl_lock_unhold+0x37/0x130 [obdclass]
[<ffffffffa09e3598>] lov_sublock_release+0x1a8/0x2a0 [lov]
[<ffffffffa09e619b>] lov_lock_enqueue+0x2cb/0x830 [lov]
[<ffffffffa05f038c>] cl_enqueue_try+0xfc/0x310 [obdclass]
[<ffffffffa05f184d>] cl_enqueue_locked+0x6d/0x210 [obdclass]
[<ffffffffa05f24ee>] cl_lock_request+0x7e/0x280 [obdclass]
[<ffffffffa0b096bb>] cl_glimpse_lock+0x17b/0x4a0 [lustre]
[<ffffffffa0b09f47>] cl_glimpse_size0+0x187/0x190 [lustre]
[<ffffffffa0ac6f62>] ll_inode_revalidate_it+0xf2/0x1c0 [lustre]
[<ffffffffa0f59154>] ? cfs_hash_dual_bd_unlock+0x34/0x60 [libcfs]
[<ffffffffa0ac7079>] ll_getattr_it+0x49/0x170 [lustre]
[<ffffffffa0ac71d7>] ll_getattr+0x37/0x40 [lustre]
[<ffffffff812143e3>] ? security_inode_getattr+0x23/0x30
[<ffffffff81180571>] vfs_getattr+0x51/0x80
[<ffffffff8118082f>] vfs_fstat+0x3f/0x60
[<ffffffff81180874>] sys_newfstat+0x24/0x40
[<ffffffff810d6b12>] ? audit_syscall_entry+0x272/0x2a0
[<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b
===========================================
I still haven't been able to run with a full Lustre-2.1 Clients/Servers config due to Toro's current over-booking and me actually not able to run my own builds on Toro's VMs (but I am working on that !!).
Do you want to have a look at the current situation I left as-is on client-12vm[1-4], client-[15,17] ??
|
|
Tell me because I need to give back my reservations on Toro ...
|
|
it looks like the client was evicted and then it was hung at unregistering reply, this caused the write RPC couldn't be erred out so it was stuck there.
It showed two problems here:
1. why was the client evicted? From the message on the OST, the client didn't ping the OSTs in 50 seconds;
2. why couldn't the client unregister the reply of that write RPC - I need help from lnet expert to address it.
Thanks,
|
|
FYI: this problem happened on client-12vm4...
|
|
I just looked at the logs on client-12vm4. Unfortunately, there are no LNet logs. If this can be easily reproduced  , would it be possible to run 'echo +neterror > /proc/sys/lnet/printk' on the clients first so that network errors will be logged?
|
|
Hi Bruno, can you please run the test again and turn on neterror?
|
|
Ok it is running as you requested, I will let you know as soon as it triggers ...
|
|
Humm looks not so easy to reproduce, actually reproducer is running/looping since more than 2 days now ... Trying to introduce some impact like umount/mount and "echo 3>drop_caches" between each run.
|
|
Tell me when you are done that I can return the Nodes reservation ...
|
|
Hi Doug, can you please take a look at it?
|
|
Took a look at the logs for client-12vm3. Bruno is right, there were no LNet logs so packet loss was not an issue/cause here.
Question: I'm no familiar with this test, but why does ptlrpc continuously complain in the logs about the network being sluggish?
I went back in the logs until just before the sluggish logs started. Here is what started the complaining:
The sluggish logs repeat until Dec 10 04:09:37 at which time the task is detected as hung.
Is this expected behaviour of this test?
|
|
Sorry Doug, you may wait from some feedback here, so yes this are the msgs that we can see when we reproduce the hung situation, and the current hung thread stack on Client too.
|
|
Jinshan,
As I keep Toro reservations since quite a long time for this problem/reproducer, I need to free them now due to higher priority tests to be done on the cluster. So i decided to freeze the Nodes situations by 1st taking a "dump live" image of the 4 client-12vm[1-4] VMs with virsh and then I crashed all Nodes+VMs with Alt+SysRq sequence. All these infos are now available under brent:~bruno/LU-874/new_hang_101212.
|
|
Thank you Bruno.
|
|
Bruno, it would have been great if together with vmcore files you'd put lustre modules rpm and the kernel-debuginfo so that they are useful for everybody.
From my look it seems Bobijam analysus from Oct 16 is pretty much what I would think.
There's an extra piece here that explains it all. Reply for the RPC is not processed because ptlrpcd is locked up trying to get mutex, as the result, RPC (reply arrived based on flags) is stuck on the sending list and could not be taken out (also job for ptlrpcd that is locked up).
|
|
You are right I had to be quick and did not save the necessary symbol stuff, but at this moment it was not intended to serve after more than a month and also I thought all could be easily retrieved with their build versions (saved in job_hang.txt file) ... But if finally not, you are right that's a good experience to learn from for next time.
If you want I can reproduce it again on Toro ?
And according to your analysis we need to pursue with http://review.whamcloud.com/4306 ?
|
|
I am not working on this issue myself, I had a discussion with Jinshan yesterday and I believe we now agree the reason for this particular problem is understood.
Jinshan is now thinking on how to properly address it and patch 4306 might be the move in the right direction, but I'll defer to him.
The old rule of "ptlrpcd should not block" is still very important, when it's violated, all async ptlrpcd-handled RPCs are at risk of being stuck because their replies could not be handled.
|
|
I will try to make a patch tomorrow.
|
|
Hi Bruno Faccini, can you please try to check if this works: http://review.whamcloud.com/5208
|
|
Not reproduced during the week-end, I keep trying using different Clients/Servers scenarios/configs.
|
|
Jinshan, we are now with 2 more days (total of more than 5 now !) of testing this latest patch on 2 different clusters running with multiple configurations, with heavy reproducer exposure. But still no hang reproduction.
|
|
Thank you Bruno, let's start the landing process then.
|
|
LU-2683 is the release blocker.
|
|
Jinshan, I post this here since I think it belongs to this JIRA !!
So again, no more occurence with reproducer and also others tests/work-loads when running with http://review.whamcloud.com/5208 patch #2, since more than 2 full days now.
|
|
Thank you Bruno. Let's land 5208 in this case.
|
|
I noticed that http://review.whamcloud.com/5208 was committed to master but not to b2_1, while all of the other patches committed for LU-874 have been applied to both trees. Oversight?
|
|
Stephen, I just back-ported Change #5208 (patch-set #2) as part of LU-2683.
|
|
Can we close this please
|
Generated at Sat Feb 10 01:11:13 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
874pdf.pdf
LU-874.lustre-log.oss.1322741854.6037.gz
lc3-OST001_brw_stats.txt