[LU-11125] ofd_create_hdl() destroys_in_progress already cleared Created: 06/Jul/18 Updated: 03/Jan/19 Resolved: 01/Sep/18 |
|
| Status: | Resolved |
| Project: | Lustre |
| Component/s: | None |
| Affects Version/s: | Lustre 2.10.4 |
| Fix Version/s: | Lustre 2.12.0, Lustre 2.10.6 |
| Type: | Bug | Priority: | Major |
| Reporter: | Olaf Faaland | Assignee: | Mikhail Pershin |
| Resolution: | Fixed | Votes: | 0 |
| Labels: | llnl | ||
| Environment: |
lustre-2.10.4_1.chaos-1.ch6.x86_64 servers |
||
| Issue Links: |
|
||||||||
| Severity: | 3 | ||||||||
| Rank (Obsolete): | 9223372036854775807 | ||||||||
| Description |
|
Servers were restarted and appeared to recover normally. They briefly appeared to be handling the same (heavy) workload from before they were powered off, then started logging the "system was overloaded" message. The kernel then reported several stacks like this: INFO: task ll_ost00_007:108440 blocked for more than 120 seconds. And lustre began reporting:
|
| Comments |
| Comment by Olaf Faaland [ 06/Jul/18 ] |
|
Note this is not the same system as the one we reported an issue with earlier today. |
| Comment by Olaf Faaland [ 06/Jul/18 ] |
|
At the same time this was occurring, an aarch64 system running a 2.11 client was trying to connect unsuccessfully with these servers (the file system is mounted on the 2.11 nodes but the map_on_demand setting was changed on the servers and the connection attempts are all failing). /tmp/lustre-log.XXX files were being created, with contents like this: 00000800:00000100:13.0:1530842270.070848:0:114359:0:(o2iblnd_cb.c:2672:kiblnd_rejected()) 172.19.1.23@o2ib100 rejected: no listener at 987 00000800:00000100:13.0:1530842271.070330:0:114359:0:(o2iblnd_cb.c:2646:kiblnd_check_reconnect()) 172.19.1.23@o2ib100: reconnect (invalid service id), 12, 12, msg_size: 4096, queue_depth: 8/-1, max_frags: 256/-1 00000800:00000100:13.0:1530842271.070337:0:114359:0:(o2iblnd_cb.c:2672:kiblnd_rejected()) 172.19.1.23@o2ib100 rejected: no listener at 987 00000800:00000100:13.0:1530842272.070954:0:114359:0:(o2iblnd_cb.c:2646:kiblnd_check_reconnect()) 172.19.1.23@o2ib100: reconnect (invalid service id), 12, 12, msg_size: 4096, queue_depth: 8/-1, max_frags: 256/-1 00000800:00000100:13.0:1530842272.070957:0:114359:0:(o2iblnd_cb.c:2672:kiblnd_rejected()) 172.19.1.23@o2ib100 rejected: no listener at 987 00000800:00000100:13.0:1530842273.071332:0:114359:0:(o2iblnd_cb.c:2646:kiblnd_check_reconnect()) 172.19.1.23@o2ib100: reconnect (invalid service id), 12, 12, msg_size: 4096, queue_depth: 8/-1, max_frags: 256/-1 00000800:00000100:13.0:1530842273.071336:0:114359:0:(o2iblnd_cb.c:2672:kiblnd_rejected()) 172.19.1.23@o2ib100 rejected: no listener at 987 00000800:00000100:5.0:1530842274.071750:0:70765:0:(o2iblnd_cb.c:490:kiblnd_rx_complete()) Rx from 172.19.1.23@o2ib100 failed: 5 00000800:00000100:13.0:1530842274.071790:0:114359:0:(o2iblnd_cb.c:2646:kiblnd_check_reconnect()) 172.19.1.23@o2ib100: reconnect (invalid service id), 12, 12, msg_size: 4096, queue_depth: 8/-1, max_frags: 256/-1 00000800:00000100:13.0:1530842274.071793:0:114359:0:(o2iblnd_cb.c:2672:kiblnd_rejected()) 172.19.1.23@o2ib100 rejected: no listener at 987 00002000:00020000:9.0:1530842274.090444:0:102598:0:(ofd_dev.c:1627:ofd_create_hdl()) lquake-OST0002:[28991030285] destroys_in_progress already cleared 00000100:00000400:8.0:1530842274.090453:0:102596:0:(service.c:2114:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (755:203s); client may timeout. req@ffff8bb9b7e93850 x1605203337942624/t0(0) o5->lquake-MDT0003-mdtlov_UUID@172.19.1.114@o2ib100:296/0 lens 432/400 e 0 to 0 dl 1530842071 ref 1 fl Complete:/0/0 rc 0/0 00000800:00000100:13.0:1530842275.071508:0:114359:0:(o2iblnd_cb.c:2646:kiblnd_check_reconnect()) 172.19.1.23@o2ib100: reconnect (invalid service id), 12, 12, msg_size: 4096, queue_depth: 8/-1, max_frags: 256/-1 00000800:00000100:13.0:1530842275.071516:0:114359:0:(o2iblnd_cb.c:2672:kiblnd_rejected()) 172.19.1.23@o2ib100 rejected: no listener at 987 00000800:00000400:8.0:1530842276.068989:0:70764:0:(o2iblnd_cb.c:3192:kiblnd_check_conns()) Timed out tx for 172.19.1.23@o2ib100: 25 seconds 00000800:00000100:13.0:1530842276.070940:0:114359:0:(o2iblnd_cb.c:2646:kiblnd_check_reconnect()) 172.19.1.23@o2ib100: don't reconnect (no need), 12, 12, msg_size: 4096, queue_depth: 8/-1, max_frags: 256/-1 OST0002 and OST0003 both reported "destroys_in_progress already cleared", and both reported dumping /tmp/lustre-log files, but the node hosting OST0002 was rebooted and those log files were lost. So the content above is from a different OST, but it was also reporting the same stacks and console messages. |
| Comment by Peter Jones [ 06/Jul/18 ] |
|
Mike Could you please investigate? Thanks Peter |
| Comment by Mikhail Pershin [ 09/Jul/18 ] |
|
Olaf, are there any other bad effects except stack dumps and LustreError messages? Do OSTs works normal after all? You mentioned that OST0002 was rebooted, was that because of this issue or planned restart? |
| Comment by Olaf Faaland [ 09/Jul/18 ] |
|
Mike, at the time several IORs were running and they all appeared not to resume progress after recovery completed. ltop was showing no activity on the file system, and the IORs were not finishing at the expected pace. Later, the problem seemed to resolve itself - all but one of the IORs completed successfully, but several took 10-20 times longer than they should have. I'm looking into that now to get more information. One compute node crashed, but due to an unrelated problem we have neither the stack nor the crash dump. We're looking into that problem as well.
|
| Comment by Olaf Faaland [ 09/Jul/18 ] |
|
I was mistaken about OST0002 being rebooted a second time. The file system was restarted just once, and the symptoms described here were seen after they came up and completed recovery.
|
| Comment by Olaf Faaland [ 09/Jul/18 ] |
|
I am going to attempt to re-create this without the complication of the Lustre 2.11 arm system mounting the file system. |
| Comment by Mikhail Pershin [ 10/Jul/18 ] |
|
That message - "destroys_in_progress already cleared" - related just to MDT->OST reconnects and may happen when MDT reconnects due to some reasons but OST is still performing orphan destroys from previous connect. I see in logs in description this: 00002000:00020000:9.0:1530842274.090444:0:102598:0:(ofd_dev.c:1627:ofd_create_hdl()) lquake-OST0002:[28991030285] destroys_in_progress already cleared 00000100:00000400:8.0:1530842274.090453:0:102596:0:(service.c:2114:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (755:203s); client may timeout. req@ffff8bb9b7e93850 x1605203337942624/t0(0) o5->lquake-MDT0003-mdtlov_UUID@172.19.1.114@o2ib100:296/0 lens 432/400 e 0 to 0 dl 1530842071 ref 1 fl Complete:/0/0 rc 0/0 Looks like second thread [102598] was waiting for the first [102596] to complete OST_CREATE request with orphan destroys. And that first one took quite long time. It seems the problem is in that long orphan destroy, something was blocking it for quite a time. That can be just result of overall high load upon OST restart |
| Comment by Olaf Faaland [ 10/Jul/18 ] |
|
Thank you for the explanation.
It sounds like destroys_in_progress should be a CDEBUG message, since it can occur under normal operating conditions.
|
| Comment by Mikhail Pershin [ 11/Jul/18 ] |
|
It still may indicate the problem there, there are two different operations are possible on OST restart - MDT initiates orphan destroys, but also new precreates may be initiated by write replays. Both uses the same mutex 'os_create_lock' though one process destroys non-used objects and other creates new objects. That causes high contention on that mutex exactly on OST restart and I am checking now is that possible to separate locking for both processes. That would relieve load on that mutex. |
| Comment by Olaf Faaland [ 13/Aug/18 ] |
|
Hello Mikhail, have you learned anything more of interest? Thanks. |
| Comment by Mikhail Pershin [ 13/Aug/18 ] |
|
Olaf, this message is not an error so it can be just made less noisy as first step and then I will create new improvement ticket to investigate this area thoughtfully to lower contention on that mutex during OST recovery |
| Comment by Gerrit Updater [ 13/Aug/18 ] |
|
Mike Pershin (mpershin@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/32985 |
| Comment by Gerrit Updater [ 01/Sep/18 ] |
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/32985/ |
| Comment by Peter Jones [ 01/Sep/18 ] |
|
This first patch landed for 2.12. Mike, can you please link in the ticket tracking the subsequent improvement? |
| Comment by Gerrit Updater [ 01/Sep/18 ] |
|
Minh Diep (mdiep@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/33100 |
| Comment by Gerrit Updater [ 11/Sep/18 ] |
|
John L. Hammond (jhammond@whamcloud.com) merged in patch https://review.whamcloud.com/33100/ |
| Comment by Olaf Faaland [ 18/Sep/18 ] |
|
Is there a ticket for reducing the contention on os_create_lock? Thanks. |
| Comment by Olaf Faaland [ 19/Sep/18 ] |
|