[LU-9949] lolnd broken

• Type: Bug
• Resolution: Duplicate
• Priority: Major
• Severity: 3
• Assignee: Amir Shehata (Inactive)
• Reporter: Oleg Drokin

Description

It looks like "LU-9480 lnet: implement Peer Discovery" commit 0f1aaad4c1b4447ee5097b8bb79a49d09eaa23c2 broke lolnd (suggested by git bisect)

This manifests in e.g. sanity test 101b hanging with this in logs:

[  215.914245] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead ================================================= 01:32:15 (1504675935)
[  215.985320] Lustre: lfs: using old ioctl(LL_IOC_LOV_GETSTRIPE) on [0x200000401:0x5:0x0], use llapi_layout_get_by_path()
[  256.717500] LNet: Service thread pid 4032 was inactive for 40.01s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
[  256.720328] Pid: 4032, comm: ll_ost_io00_002
[  256.721561] 
Call Trace:
[  256.723391]  [<ffffffff81704339>] schedule+0x29/0x70
[  256.724533]  [<ffffffff81700972>] schedule_timeout+0x162/0x2a0
[  256.725651]  [<ffffffff810879f0>] ? process_timeout+0x0/0x10
[  256.726859]  [<ffffffffa0534e3e>] target_bulk_io+0x4ee/0xb20 [ptlrpc]
[  256.729276]  [<ffffffff810b7ce0>] ? default_wake_function+0x0/0x20
[  256.730431]  [<ffffffffa05ddf08>] tgt_brw_read+0xf38/0x1870 [ptlrpc]
[  256.731359]  [<ffffffffa01ba4a4>] ? libcfs_log_return+0x24/0x30 [libcfs]
[  256.732387]  [<ffffffffa0579f90>] ? lustre_pack_reply_v2+0x1a0/0x2a0 [ptlrpc]
[  256.733578]  [<ffffffffa0532800>] ? target_bulk_timeout+0x0/0xb0 [ptlrpc]
[  256.734845]  [<ffffffffa057a102>] ? lustre_pack_reply_flags+0x72/0x1f0 [ptlrpc]
[  256.736719]  [<ffffffffa057a291>] ? lustre_pack_reply+0x11/0x20 [ptlrpc]
[  256.737931]  [<ffffffffa05dad2b>] tgt_request_handle+0x93b/0x1390 [ptlrpc]
[  256.738981]  [<ffffffffa05853b1>] ptlrpc_server_handle_request+0x251/0xae0 [ptlrpc]
[  256.740764]  [<ffffffffa0589168>] ptlrpc_main+0xa58/0x1df0 [ptlrpc]
[  256.741800]  [<ffffffff81706487>] ? _raw_spin_unlock_irq+0x27/0x50
[  256.742938]  [<ffffffffa0588710>] ? ptlrpc_main+0x0/0x1df0 [ptlrpc]
[  256.743943]  [<ffffffff810a2eda>] kthread+0xea/0xf0
[  256.744963]  [<ffffffff810a2df0>] ? kthread+0x0/0xf0
[  256.745913]  [<ffffffff8170fbd8>] ret_from_fork+0x58/0x90
[  256.746933]  [<ffffffff810a2df0>] ? kthread+0x0/0xf0

[  256.748798] LustreError: dumping log to /tmp/lustre-log.1504675975.4032
[  269.494952] LustreError: 2624:0:(events.c:449:server_bulk_callback()) event type 5, status -5, desc ffff8800720b3e00

Easy to reproduce, just run this on a single node: ONLY=101 REFORMAT=yes sh sanity.sh

Issue Links

• duplicates: LU-9992 Multi-Rail: use lolnd when sending locally
• is related to: LU-9992 Multi-Rail: use lolnd when sending locally

Comments

[Peter Jones]

Sounds like a duplicate 

[Amir Shehata (Inactive)]

According to Alex: yes, it's safe as page is removed from the mapping (so another threads can't find it), but it can't get reused for anything else until last page_put() is called

to summarize, the issue seems to be observed only on Oleg's VM on a single node setup running a debug kernel. It appears that calling generic_error_remove_page() which unmaps the pages before they are sent by the socklnd causes the socklnd send to succeed, but not to actually send the pages. It is still not known exactly why that happens.

This issue occurred after 0f1aaad4c1b4447ee5097b8bb79a49d09eaa23c2 which discovers the loopback interface when it's initially used then due to the lolnd having no credits always prefers the other interfaces. This issue has been resolved in LU-9992.

Should this still be a blocker?

[Amir Shehata (Inactive)]

One outstanding question that should be answered: Is it safe for generic_error_remove_page() to be called on the pages before they are passed to the LND?

[Oleg Drokin]

Multinode setup appears to be working ok

[John Hammond]

> I believe that lnet is smart enough to use lolnd when it notices that the target nid is the same as its own.

This is no longer the case after 0f1aaad4c1b4447ee5097b8bb79a49d09eaa23c2 LU-9480 lnet: implement Peer Discovery. Which seems like a bug.

[John Hammond]

Oleg have you tested this on a multiple node setup using the same debug kernel?

[Amir Shehata (Inactive)]

The problem happens when read_cache_enable=0. If read_cache_enable=1 then the test passes (both 101b and John's reproducer)

In the case when read_cache_enable=0 generic_error_remove_page() is being called for each page in osd_read_prep(). Looking at this function it unmaps the pages. This seems to cause a problem on Oleg's setup. After the pages are unmapped the socklnd does not seem to complete the bulk transfer. The server appears to call the kernel API to send the page, but the client socklnd (which is common with the server, since it's the same node) never receives the data.

I haven't been able to reproduce this issue on my local VM. Oleg's VM is running a debug Kernel, and I'm wondering if its behavior is different. I'll attempt to step through the code and see if the data is being dropped somewhere in the kernel call stack.

[James A Simmons]

I'm seeing this from time to time which is preventing me from mounting a test file system.

00000020:00000080:4.0:1505255706.626213:0:6697:0:(obd_config.c:431:class_attach()) OBD: dev 1 attached type mgc with refcount 1
00000020:00000080:4.0:1505255706.626217:0:6697:0:(obd_config.c:1138:class_process_config()) processing cmd: cf003
00000100:00000100:5.0:1505255706.627789:0:6697:0:(client.c:96:ptlrpc_uuid_to_connection()) cannot find peer MGC10.37.248.196@o2ib1
_0!
00010000:00080000:5.0:1505255706.627791:0:6697:0:(ldlm_lib.c:74:import_set_conn()) can't find connection MGC10.37.248.196@o2ib1_0
00010000:00020000:5.0:1505255706.627793:0:6697:0:(ldlm_lib.c:483:client_obd_setup()) can't add initial connection
00000020:00000080:1.0:1505255706.638190:0:6711:0:(genops.c:1204:class_import_destroy()) destroying import ffff88101ff0a000 for MGC
10.37.248.196@o2ib1
00000020:00020000:6.0:1505255706.639014:0:6697:0:(obd_config.c:563:class_setup()) setup MGC10.37.248.196@o2ib1 failed (-2)
00000020:00020000:6.0:1505255706.650104:0:6697:0:(obd_mount.c:202:lustre_start_simple()) MGC10.37.248.196@o2ib1 setup error -2
00000020:00000080:6.0:1505255706.661495:0:6697:0:(obd_config.c:1138:class_process_config()) processing cmd: cf002

Is this the same bug or such I open another ticket?

[John Hammond]

Simplified reproducer (on a single Oleg test node):

dd if=/dev/zero of=/mnt/lustre/f1 bs=1M count=1
lctl set_param ldlm.namespaces.*-osc-*.lru_size=clear
lctl set_param osd-ldiskfs.*.read_cache_enable=0
dd if=/mnt/lustre/f1 of=/dev/null bs=1M

[Oleg Drokin]

I believe that lnet is smart enough to use lolnd when it notices that the target nid is the same as its own.