[LU-4308] MPI job causes errors "binary changed while waiting for the page fault lock" Created: 25/Nov/13  Updated: 28/Jan/16  Resolved: 14/Aug/14

Status: Resolved
Project: Lustre
Component/s: None
Affects Version/s: Lustre 2.4.1
Fix Version/s: Lustre 2.5.3

Type: Bug Priority: Minor
Reporter: Blake Caldwell Assignee: Zhenyu Xu
Resolution: Fixed Votes: 5
Labels: None
Environment:

RHEL 6.4/MLNX OFED 2.0.2.6.8.10


Issue Links:
Related
is related to LU-7198 vvp_io.c:701:vvp_io_fault_start()) bi... Resolved
Severity: 4
Rank (Obsolete): 11800

 Description   

When a MPI job is run, we see many of these messages "binary x changed while waiting for the page fault lock." Is this normal behavior or not? It was also reported here.

https://lists.01.org/pipermail/hpdd-discuss/2013-October/000560.html

Nov 25 13:46:50 rhea25 kernel: Lustre: 105703:0:vvp_io.c:699:vvp_io_fault_start()) binary [0x20000f81c:0x18:0x0] changed while waiting for the page fault lock
Nov 25 13:46:53 rhea25 kernel: Lustre: 105751:0:(vvp_io.c:699:vvp_io_fault_start()) binary [0x20000f81c:0x19:0x0] changed while waiting for the page fault lock
Nov 25 13:46:57 rhea25 kernel: Lustre: 105803:0:(vvp_io.c:699:vvp_io_fault_start()) binary [0x20000f81c:0x1a:0x0] changed while waiting for the page fault lock
Nov 25 13:46:57 rhea25 kernel: Lustre: 105803:0:(vvp_io.c:699:vvp_io_fault_start()) Skipped 1 previous similar message
Nov 25 13:47:00 rhea25 kernel: Lustre: 105846:0:(vvp_io.c:699:vvp_io_fault_start()) binary [0x20000f81c:0x1b:0x0] changed while waiting for the page fault lock
Nov 25 13:47:00 rhea25 kernel: Lustre: 105846:0:(vvp_io.c:699:vvp_io_fault_start()) Skipped 2 previous similar messages
Nov 25 13:47:07 rhea25 kernel: Lustre: 105942:0:(vvp_io.c:699:vvp_io_fault_start()) binary [0x20000f81c:0x1d:0x0] changed while waiting for the page fault lock



 Comments   
Comment by Peter Jones [ 25/Nov/13 ]

Hi Blake

I will get an engineer to comment asap, but just to clarify - is this really an S1 situation (i.e. a production cluster is completely inoperational)?

Peter

Comment by Blake Caldwell [ 25/Nov/13 ]

It should be severity 4

Comment by Peter Jones [ 25/Nov/13 ]

Thanks for clarifying Blake.

Alex

Could you please comment?

Thanks

Peter

Comment by Zhenyu Xu [ 13/Jan/14 ]

Blake,

This message means that a mmapped executable file is under read while other threads may change its contents. Is this what the MPI job meant to do, ie. generating executable files while other jobs reading it?

Comment by Peter Jones [ 20/Feb/14 ]

As per ORNL ok to close

Comment by Jason Hill (Inactive) [ 07/Mar/14 ]

Hate to open something we said to close last week, but we have another occurrence of this issue on the same cluster. We are consulting with the sysadmin for that cluster, and likely with the user to discuss the question from Zhenyu.

Mar 6 16:49:55 rhea101 kernel: Lustre: 24431:0:(vvp_io.c:699:vvp_io_fault_start()) binary [0x20006c6eb:0xc:0x0] changed while waiting for the page fault lock


-Jason

Comment by Jesse Stroik [ 29/Apr/14 ]

We are observing a similar issue and sometimes see the same error. It only happens when we run specific jobs that use MPI with OpenMP threads. Those same jobs complete when using pure MPI.

Symptoms:

  • The file in question cannot be read on some specific clients (but can on most other clients)
  • On those nodes where it cannot be read, processes that need to access /proc/PID/cmdline for the process executing that file block (w, ps, etc).
  • File system can no longer unmount.
  • sometimes clients will have open FIDs that cannot resolve to paths when we get the list of FIDs held open by the client on the MDS.

Effectively, we have to power cycle or reboot -fn to get the nodes in question back up.

The file in question can be read by other lustre clients. We tested running lustre client and server 2.4.2 and 2.5.1. Same results for both. To reduce the chance this is an MPI bug, we also tested on two versions of Intel MPI (4.1.0.024 and 4.1.3.049) and Intel compilers 13.1 and 14.0-1. To reduce the risk of race conditions, we pin MPI threads to a single socket.

Here is a bit of strace for cp:

===============
stat("/scratch/short/jimj/s4_1534/stmp_2013062412_gdas_fcst1/global_fcst",

{st_mode=S_IFREG|0755, st_size=24534300, ...}) = 0
stat("./global_fcst", 0x7fffb2d95eb0) = -1 ENOENT (No such file or directory)
open("/scratch/short/jimj/s4_1534/stmp_2013062412_gdas_fcst1/global_fcst", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0755, st_size=24534300, ...}

) = 0
open("./global_fcst", O_WRONLY|O_CREAT|O_EXCL, 0755) = 4
fstat(4,

{st_mode=S_IFREG|0755, st_size=0, ...}

) = 0
mmap(NULL, 4202496, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b5b721c5000
read(3,
===============

At that point, it hangs indefinitely.

For us, this may be a blocking issue. We're not sure where exactly the blame lies, but it does seem suspect that the systems cannot flush bad pages or read files other lustre clients can read. We can't go into production with this hardware until we resolve this.

Comment by Jesse Stroik [ 30/Apr/14 ]

We left the clients in their broken state over night. Same deal. Then, we tested deleting the file from a bad actor and observed this:

April 29 @ 17:43
172.17.1.251 - [0x200001435:0xad:0x0] - /scratch/short/jimj/s4_1534/stmp_2013062412_gdas_fcst1/global_fcst
172.17.1.251 - [0x200001435:0x12e:0x0] -
/scratch/short/jimj/s4_1534/stmp_2013062412_gdas_fcst1/gfs_namelist

(rm the file)

April 30 @ 13:35
172.17.1.251 - [0x200001435:0xad:0x0] - No file or directory

The file handle is still stuck open on all nodes where it was unreadable. The stuck nodes cannot read the file, but they can delete it. However, even deleting it doesn't release their file handle.

Comment by Jesse Stroik [ 07/May/14 ]

I'm not confident that our issue, which I suspect is related to a bug in the lustre client, has anything to do with the error 'binary changed...'.

We did, however, revert our clients to 2.1.6 (still running server 2.5.1) and we no longer observe the same hanging file / hanging mount problem.

Comment by Zhenyu Xu [ 29/May/14 ]

Is it easy to reproduce? Can you collect -1 logs with as simple as possible reproduce procedure and upload the logs? Thank you.

Comment by Zhenyu Xu [ 29/May/14 ]

Also would you please trying this patch http://review.whamcloud.com/10483 ?

Comment by Lukasz Flis [ 14/Jul/14 ]

Is there a patch for client 2.5.1?
We are observing the same issues in Cyfronet with 2.5.1 client and mpi jobs

Jul 14 19:24:56 n1043-amd kernel: Lustre: 21837:0:(vvp_io.c:692:vvp_io_fault_start()) binary [0x20d545086:0x191e4:0x0] changed while waiting for the page fault lock
Jul 14 19:24:56 n1043-amd kernel: Lustre: 21837:0:(vvp_io.c:692:vvp_io_fault_start()) Skipped 54 previous similar messages
Jul 14 19:34:59 n1043-amd kernel: Lustre: 21813:0:(vvp_io.c:692:vvp_io_fault_start()) binary [0x20d545086:0x191e4:0x0] changed while waiting for the page fault lock
Jul 14 19:34:59 n1043-amd kernel: Lustre: 21812:0:(vvp_io.c:692:vvp_io_fault_start()) binary [0x20d545086:0x191e4:0x0] changed while waiting for the page fault lock
Jul 14 19:34:59 n1043-amd kernel: Lustre: 21812:0:(vvp_io.c:692:vvp_io_fault_start()) Skipped 75 previous similar messages
Jul 14 19:34:59 n1043-amd kernel: Lustre: 21813:0:(vvp_io.c:692:vvp_io_fault_start()) Skipped 75 previous similar messages
Jul 14 19:36:47 n1043-amd kernel: LustreError: 11-0: scratch-MDT0000-mdc-ffff882834414c00: Communicating with 172.16.193.1@o2ib, operation mds_get_info failed with -1119251304.
Jul 14 19:36:47 n1043-amd kernel: LustreError: Skipped 4 previous similar messages
Jul 14 19:45:00 n1043-amd kernel: Lustre: 21825:0:(vvp_io.c:692:vvp_io_fault_start()) binary [0x20d545086:0x191e4:0x0] changed while waiting for the page fault lock
Jul 14 19:45:00 n1043-amd kernel: Lustre: 21825:0:(vvp_io.c:692:vvp_io_fault_start()) Skipped 71 previous similar messages
Jul 14 19:55:02 n1043-amd kernel: Lustre: 21828:0:(vvp_io.c:692:vvp_io_fault_start()) binary [0x20d545086:0x191e4:0x0] changed while waiting for the page fault lock
Jul 14 19:55:02 n1043-amd kernel: Lustre: 21828:0:(vvp_io.c:692:vvp_io_fault_start()) Skipped 375 previous similar messages

Comment by Lukasz Flis [ 14/Jul/14 ]

@Zhenyu Xu: logs related to the following object have been uploaded to ftp:
Jul 14 19:55:02 n1043-amd kernel: Lustre: 21828:0:(vvp_io.c:692:vvp_io_fault_start()) binary [0x20d545086:0x191e4:0x0] changed while waiting for the page fault lock

Please find the logs here: ftp://ftp.whamcloud.com/uploads/lu-4308.cyfronet.log.gz

Comment by Zhenyu Xu [ 15/Jul/14 ]

patch for b2_5 branch http://review.whamcloud.com/11098

Comment by Aron Parsons [ 16/Jul/14 ]

We've been running 2.5.1 client packages with this patch included in two separate environments for the past month. It has eliminated these error messages from occurring.

Comment by Tommi Tervo [ 14/Aug/14 ]

I applied patch to 2.5.2 client but problem persists. It was VASP MPI jobs which triggered this error.

Lustre: 62291:0:(vvp_io.c:692:vvp_io_fault_start()) binary [0x201c53daa:0x1d27:0x0] changed while waiting for the page fault lock
Lustre: 62291:0:(vvp_io.c:692:vvp_io_fault_start()) Skipped 1 previous similar message
Lustre: 62618:0:(vvp_io.c:692:vvp_io_fault_start()) binary [0x201c53daa:0x1d27:0x0] changed while waiting for the page fault lock

Comment by Peter Jones [ 14/Aug/14 ]

The patch that has been reportedly successful at a couple of sites has been landed for 2.5.3. It is not believed that this same issue exists on 2.6 or newer releases so equivalent changes are not needed on master. If there are still residual issues affecting 2.5.x releases then please open a new ticket to track those - thanks!

Comment by Jesse Stroik [ 21/Aug/14 ]

I wanted to report back on our issue because it may be related.

Our original observation was that some of our Lustre clients would deadlock when running MPI+OpenMP executables. The executable on those clients could only be partially read, and would hang indefinitely on copy or access to /proc/<pid>/exe or /proc/<pid>/cmdline.

We upgraded to 2.5.2 and applied the aforementioned patch and observed no change.

We did test the following workarounds some of which were entirely successful:

(1) enabling 'localflock' for those clients as a mount flag was completely successful.

(2) hosting the executable on an NFS mount was completely successful.

(3) upgrading to lustre 2.6.0 was completely successful.

(4) running lustre 2.1.6 with khugepaged disabled mitigated the issue to a large extent, with rare observed deadlocks.

(5) we tried running on another lustre file system (lustre 2.4.2 servers running ZFS instead of lustre 2.5.1 running ldiskfs) but did not notice any improvement to the client deadlock issue.

We settled on running lustre 2.6.0 on the clients because we also observed a performance increase when using it.

NOTE: this issue may have been related to an irregularity we observed in slurmd and have found a work around for as well.

Comment by Kurt J. Strosahl (Inactive) [ 28/Jan/16 ]

We are seeing this issue on clients running 2.5.3

vvp_io.c:694:vvp_io_fault_start()) binary [0x20000aaa6:0x1d668:0x0] changed while waiting for the page fault lock

It manifested while the file system was under high load.

Generated at Sat Feb 10 01:41:33 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.