|
Lai
Could you please look into this one?
Thanks
Peter
|
|
Roger, the first backtrace is a warning, the panic information is lost (refer to usrs393.netconsole), is it possible to setup kdump and get crash data? or connect a serial console and get panic info? I'll try to reproduce in my setup too.
The second backtrace shows a slow thread on OST, which should not be relative to the panic.
|
|
/var/log/messages from system with the problem.
|
|
From the customer:
Attached is the appropriate portion of /var/log/messages from that date - it had more info then the netconsole because apparently the problem was in the softirq and the network driver couldn't send anymore. Unfortunately the serial connections very often don't have anything on them for whatever reason and we haven't been able to get kdump to work in our environment. I currently have another client that is locked up on probably the same issue.
|
|
Yes, the log shows there are some network IO problem, but it's still a warning, is it possible to get the crash backtrace?
|
|
The customer is unable to provide a crash backtrace. Are you able to reproduce the problem in-house with the provided test application?
|
|
Not yet, I'll keep it running.
|
|
This has been run for several days, but not produced in my test environment.
I used `while true; do sh reproduce.sh || break; done`, and I saw a few mkdir failures (looks to be failed on -EEXIST, this may be okay), everything else looks fine.
|
|
Customer reports:
I was able to verify I still see this problem this morning, additionally I think I have distilled it down to an even smaller test case with a single client.
I have a directory (generated from the test case I sent you) that has 34853 files in it. If I execute the following:
$ lfs find <dir> -type f | sh -c 'while read line; do stat ${line} < /dev/null > /dev/null & done'
This will attempt to stat the files in parallel and I see a bunch of errors that it can't find the files. However if I stat the files sequentially, everything is ok:
$ lfs find <dir> -type f | sh -c 'while read line; do stat ${line} < /dev/null > /dev/null; done'
Lai, please see if you can reproduce using this method.
Regarding the EXIST, customer responded:
As far as I know we don't see EEXIST. Every time I've seen a problem it has been a FileNotFoundException caused by ENOENT. I ran the test case I gave you this morning using "strace -f" and here is a snippet of one of the logs that failed:
[pid 22808] open("/mnt/lustre /filetest/usrs398/20120507-092516/d5/7/75.bin", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 79 [pid 22808] fstat(79,
{st_mode=S_IFREG|0664, st_size=0, ...}) = 0
[pid 22808] fcntl(79, F_GETFD) = 0
[pid 22808] fcntl(79, F_SETFD, FD_CLOEXEC) = 0 [pid 22808] write(79, "K\304\215f\361R\351\226\340Hh\32i\303\233\243t\20\301\34\313A\243\254\224\n\262\211^\202\215\20"..., 1024) = 1024 [pid 22808] open("/mnt/lustre/ filetest/usrs398/20120507-092516/d5/7/76.bin", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 80 [pid 22808] fstat(80, {st_mode=S_IFREG|0664, st_size=0, ...}
) = 0
[pid 22808] fcntl(80, F_GETFD) = 0
[pid 22808] fcntl(80, F_SETFD, FD_CLOEXEC) = 0 [pid 22808] write(80, "K\304\215f\361R\351\226\340Hh\32i\303\233\243t\20\301\34\313A\243\254\224\n\262\211^\202\215\20"..., 1024) = 1024 [pid 22808] open("/mnt/lustre/ filetest/usrs398/20120507-092516/d5/7/77.bin", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 ENOENT (No such file or directory) [pid 22808] lseek(3, 49747007, SEEK_SET) = 49747007 [pid 22808] read(3, "PK\3\4\n\0\0\0\0\0I\nj?0\341^$j\2\0\0j\2\0\0#\0\0\0", 30) = 30 [pid 22808] lseek(3, 49747072, SEEK_SET) = 49747072 [pid 22808] read(3, "\312\376\272\276\0\0\0001\0\"\10\0\4\10\0\5\10\0\n\1\0\0\1\0\2 (\1\0\24()"..., 618) = 618 [pid 22808] write(2, "Exception in thread \"main\" ", 27Exception in thread "main" ) = 27 [pid 22808] write(2, "java.io.FileNotFoundException: /"..., 127java.io.FileNotFoundException: /mnt/lustre/ filetest/usrs398/20120507-092516/d5/7/77.bin (No such file or directory)) = 127
[pid 22808] write(2, "\n", 1) = 1
[pid 22808] write(2, "\tat java.io.FileOutputStream.ope"..., 48 at java.io.FileOutputStream.open(Native Method)) = 48
[pid 22808] write(2, "\n", 1) = 1
[pid 22808] write(2, "\tat java.io.FileOutputStream.<in"..., 62 at java.io.FileOutputStream.<init>(FileOutputStream.java:194)) = 62
[pid 22808] write(2, "\n", 1) = 1
[pid 22808] write(2, "\tat java.io.FileOutputStream.<in"..., 62 at java.io.FileOutputStream.<init>(FileOutputStream.java:145)) = 62
[pid 22808] write(2, "\n", 1) = 1
[pid 22808] write(2, "\tat Reproduce.main(Reproduce.jav"..., 37 at Reproduce.main(Reproduce.java:31)) = 37
[pid 22808] write(2, "\n", 1) = 1
You can see that 2 opens succeeded with writes and the third failed. They were all writing to the same directory so that means the directory existed, just for some reason the third open returned ENOENT instead of succeeding. open(2) says:
ENOENT O_CREAT is not set and the named file does not exist. Or, a directory component in pathname does not exist or is a dan-
gling symbolic link.
Since O_CREAT is given and all directory components exist since previous writes succeeded, there must be a bug in Lustre somewhere. What about the simple script where I tried to stat the files in parallel. Did you pass that on to Whamcloud as (on the surface) it appears to be a similar problem.
|
|
I can't reproduce with the 'stat' script yet; maybe my test machine is not powerful enough, and there isn't a machine installed with fc15 in testlab.
With a small tweak of your script, it can dump debug log upon error:
lfs find <dir> -type f | sh -c 'while read line; do stat ${line} < /dev/null > /dev/null || lctl dk /tmp/`basename $line`.log & done'
Could you test this script on your environment?
|
|
I've setup 3 nodes on testlab, 1 is server installed el6, 2 clients with kernel 2.6.38, and both clients doing stat and reproduce.sh in a loop. I have run test for half a day, but haven't reproduced yet, and I'll keep them running, and will add another client tomorrow if not reproduce yet.
|
|
I can't reproduce over night, now there are 300k files total in test system, could you tell me how many files are in your system when the error appeared? Could you upload messages files of both client and MDS at failure time?
|
|
Results from requested script change
lfs find <dir> -type f | sh -c 'while read line; do stat ${line} < /dev/null > /dev/null || lctl dk /tmp/`basename $line`.log & done'
|
|
This looks to be a MDS issue about OPEN lock, I have a patch at http://review.whamcloud.com/#change,2800, will you compile it against master, update MDS and test again?
|
|
Customer asks:
> What version of the kernel is Whamcloud testing with? Are they using 2.6.38.2 or a newer version of 2.6.38?
|
|
I'm testing with 2.6.38.6-26.
|
|
Please verify that the patch only touches one file.
|
|
Please verify that this only affects the Lustre server, not the client.
|
|
Yes, the patch affects Lustre MDS server only, and only touches one file.
|
|
We applied the patch. The customer reports the following:
$ lfs find . -type f | sh -c 'while read file; do stat $file & done >/dev/null'
stat: cannot stat `./20120507-091222/d3/3/270.bin': No such file or directory
stat: cannot stat `./20120507-091222/d5/32/681.bin': No such file or directory
stat: cannot stat `./20120507-091222/d5/32/1525.bin': No such file or directory
stat: cannot stat `./20120507-091222/d12/0/284.bin': No such file or directory
stat: cannot stat `./20120507-091222/d12/0/1037.bin': No such file or directory
stat: cannot stat `./20120507-091222/d12/0/917.bin': No such file or directory
stat: cannot stat `./20120507-091222/d11/32/1807.bin': No such file or directory
stat: cannot stat `./20120507-091222/d10/6/2587.bin': No such file or directory
stat: cannot stat `./20120507-091222/d10/6/891.bin': No such file or directory
stat: cannot stat `./20120507-091222/d10/6/750.bin': No such file or directory
stat: cannot stat `./20120507-091222/d7/34/151.bin': No such file or directory
Here are some additional details:
This is a single client with 24 cores running the test.
"ls -l' on each file succeeds - if I perform the stat sequentially it succeeds - it only fails when I launch the stat processes in the background thus making them parallel.
Each time I run the test, I get different files that can't be found.
|
|
Is there any error message on MDS server?
|
|
I have no way to debug without debug logs and messages; it would really to useful to dump debuglog upon error on both client and MDS, and it's best to enable 'info' and 'vfstrace' debug trace, you can check it by `lctl get_param debug`, if it doesn't contain 'info' or 'vfstrace', you can enable it with `lctl set_param debug=+"info vfstrace"`.
|
|
This is the messages file from the MDS.
|
|
> I have no way to debug without debug logs and messages; it would really to useful to dump debuglog upon error on both client and MDS, and it's best to enable 'info' and 'vfstrace' debug trace, you can check it by `lctl get_param debug`, if it doesn't contain 'info' or 'vfstrace', you can enable it with `lctl set_param debug=+"info vfstrace"`.
I will ask the customer to enable these. Are these enabled on both the client and servers?
|
|
What command is run to get view the debug data?
|
|
Yes, it's better to enable debug trace on both client and server. Upon error, you can run `lctl dk /tmp/create.log`, then you can check debug trace in the log file, which contains recent debug traces, and this is why this command should be run immediately after error occurs, otherwise the old debug trace is dropped.
|
|
This file contains client.out and mds.out with the debug info you requested.
|
|
When is the test conducted?
I saw two lines of error messages suspicious in messages.mds, but they are at May 21 23:00:01:
May 21 23:00:01 ts-xxxxxxxx-01 kernel: LustreError: 6386:0:(mdt_open.c:1472:mdt_reint_open()) open [0x200000400:0xa:0x0]/(logdates->[0x2003acec9:0x1:0x0]) cr_flag=01102 mode=0042775 msg_flag=0x0 failed: -21
May 21 23:00:01 ts-xxxxxxxx-01 kernel: LustreError: 6386:0:(mdt_open.c:1472:mdt_reint_open()) open [0x200000400:0xa:0x0]/(logdates->[0x2003acec9:0x2:0x0]) cr_flag=01102 mode=0042775 msg_flag=0x0 failed: -21
Could you upload script output along with this test? And you can use `lfs fid2path [0x2003acec9:0x1:0x0]` and `lfs fid2path [0x2003acec9:0x2:0x0]` to check which two files are failed to open.
|
|
I'm moving back to this thread to continue the file issue since it had gotten merged in with the OST failure...
I ran the test yesterday so the lines from May 21 don't pertain to the test. The two fids Lai asks about ([0x2003acec9:0x1:0x0] & [0x2003acec9:0x2:0x0]) don't exist in the file system, but I assume they were located under the directory indicated by [0x200000400:0xa:0x0] which is owned by one of our users who is more tolerant of random failures and so he hasn't been telling me about any issues he has had since he knows it is "use at your own risk" at this time.
I have uploaded a new tarball where I ran the test again. It contains the following files:
client.out - debug_kernel output from the client
mds.out - debug_kernel output from the mds
fid_mapping - mapping of fids to files for the fids found in client.out
error_fid_mapping - mapping of paths to fids and OSTs for the files that weren't found typescript - the output of "script"
The tarball is enoent-20120523.tar.gz.
|
|
The logs show that the -ENOENT files are never .lookup or .revalidate at both client and server side, so the -ENOENT error should happen in directory name lookup/revalidate. I'm a bit suspicious of 'CWD' handling in lustre: the test script calls 'stat' which calls syscall vfs_lstat() finally, and it starts pathname lookup from CWD (Current Working Directory) if filename doesn't start with '/'.
One way to prove this is to test like this:
lfs find /mnt/lustre/filetest -type f | sh -c 'while read file; do stat $file & done >/dev/null'
Then all `stat` will lookup pathname from ROOT.
BTW, please enable more debug trace in your test: `lctl set_param debug=+"vfstrace info dlmtrace dentry inode"`.
|
|
Customer reports:
It didn't make a difference - I didn't think it would since this seems to be an issue with parallel access since if I run the stats sequentially it works.
I have uploaded enoent-20120524.tar.gz:
"client.out" and "mds.out" contain the debug output.
"typescript" contains the output from the run.
"fids" contains the file names and fids for the files that weren't found.
|
|
Customer reports
If I limit the number of CPUs it can run on, it reduces the number of failures to the point where running it on 1 cpu makes it effectively sequential:
$ lfs find . -type f | taskset -c 0 sh -c 'while read file; do stat $file & done > /dev/null'
This command eventually can't fork any more processes (I reach that limit) but there are no ENOENT errors.
I see the same scenario with "taskset -c 0,1", and I see my first failure with "taskset -c 0-2", but it takes some time. However using "taskset -c 0,2" after some time I do see the ENOENT error. CPU 0 and CPU 1 are in different sockets and CPU 0 and CPU 2 are in the same socket. I do not see the error with 0 & 12 which are the hyperthreaded pairs.
I can run more tests next week if you want me to.
|
|
Hmm, it looks to be a bug in ll_splice_alias():
Once ll_splice_alias() found a reusable dentry for current inode, it will tries to reuse it, and dput() the just allocated dentry, but before that d_rehash() is called to hash this newly allocated dentry into dcache, with dentry->d_inode set to NULL. This originates from a kernel bug (d_rehash() used to be called by d_splice_alias() too), and actually it's planned to be removed in another patch, but we just think this line is redundant, and don't see it will cause error.
I'll update FC15 patchless client patch later to reflect this change.
|
|
Patch is updated: http://review.whamcloud.com/#change,2170.
Please patch it against latest master branch, and this change is for client only.
|
|
Due to recent commit, please use patch: http://review.whamcloud.com/#change,1865
|
|
Is this change just for the clients, or the servers, or both?
Do I apply both the patches from 2170 and 1865, or just 1865?
|
|
It's for client only. 2170 has been abandoned now, 1865 is the only remaining patch for FC15 patchless client support code.
|
|
The modules will not load correctly. I get the following errors:
Lustre: Lustre: Build Version: 2.2.54-g2fcae7b-CHANGED-2.6.32-220.el6.x86_64
ptlrpc: Unknown symbol lut_boot_epoch_update
ptlrpc: Unknown symbol lut_mod_exit
ptlrpc: Unknown symbol lut_mod_init
grepping through the code, I find:
lustre-release-with-patch-9/lustre/include/lu_target.h:void lut_boot_epoch_update(struct lu_target *lut);
lustre-release-with-patch-9/lustre/ldlm/ldlm_lib.c: lut_boot_epoch_update(lut);
lustre-release-with-patch-9/lustre/ldlm/ldlm_lib.c: lut_boot_epoch_update(lut);
lustre-release-with-patch-9/lustre/ptlrpc/target.c:void lut_boot_epoch_update(struct lu_target *lut)
lustre-release-with-patch-9/lustre/ptlrpc/target.c:EXPORT_SYMBOL(lut_boot_epoch_update);
So, that function is called from ldlm_lib.c.
BUT ... In the ptlrpc/Makefile, target.o is not included, i.e.
#ptlrpc_objs += target.o
|
|
you need to update to latest master branch, then patch latest Change,1865 (it's patch 21 now).
|
|
The problem still persists, i.e.
May 31 12:05:21 compute-01-32 kernel: Lustre: Lustre: Build Version: 2.2.54-g9567e22-CHANGED-2.6.32-220.el6.x86_64
May 31 12:05:21 compute-01-32 kernel: ptlrpc: Unknown symbol lut_boot_epoch_update
May 31 12:05:21 compute-01-32 kernel: ptlrpc: Unknown symbol lut_mod_exit
May 31 12:05:21 compute-01-32 kernel: ptlrpc: Unknown symbol lut_mod_init
I think I know the cause of the problem.
In the file lustre/ptlrpc/Makefile.in is the line
@SERVER_TRUE@ptlrpc_objs += target.o
After running:
./configure --with-kernel=/usr/src/kernels/2.6.32-220.el6.x86_64 \
--with-linux=/usr/src/kernels/2.6.32-220.el6.x86_64 \
--disable-liblustre \
--without-sysio \
--disable-server
The file lustre/ptlrpc/Makefile contains
#ptlrpc_objs += target.o
The file lustre/ldlm/ldlm_lib.c calls lut_boot_epoch_update(), which is defined in target.c. But, since ldlm_lib.c is compiled, but target.c is not compiled, there is an unknown symbol.
|
|
The commands I ran to get the build are:
git clone git://git.whamcloud.com/fs/lustre-release.git # svn checkout url
cd lustre-release
git fetch http://review.whamcloud.com/p/fs/lustre-release refs/changes/65/1865/21 && git checkout FETCH_HEAD
|
|
I did the same as you, but all looks well.
And where lut_boot_epoch_update() is called in ldlm_lib.c is inside #ifdef HAVE_SERVER_SUPPORT, so that these code won't be compiled, and won't cause the unknown symbol problem.
|
|
My error. I copied the wrong modules to the target system. The modules load fine now.
|
|
As I understand it, this code is being tracked for landing under LU-506
|
|
Customer reports:
It appears that this patch has fixed the original bug as the researcher was not able to replicate the problem, however he was able to panic nine of the clients with an LBUG.
See attachment for the netconsole output. The following is the output from one:
2012-06-06 11:35:51 +0000 [4026925.936063] Lustre: MGC192.168.185.35@tcp: Reactivating import
2012-06-06 11:35:52 +0000 [4026926.153312] Lustre: Mounted xxxx-client
2012-06-06 16:08:32 +0000 [4043242.176640] LustreError: 8473:0:(cl_page.c:1026:cl_page_assume()) page@ffff880f6107ad80[4 ffff880d5f11e498:0 ^ (null)_ffff880f6107ae40 1 0 1 ffff88103efcc028 (null) 0x0]
2012-06-06 16:08:32 +0000 [4043242.261214] LustreError: 8473:0:(cl_page.c:1026:cl_page_assume()) page@ffff880f6107ae40[1 ffff880fafbffda8:0 ^ffff880f6107ad80_ (null) 0 0 1 (null) (null) 0x0]
2012-06-06 16:08:32 +0000 [4043242.346779] LustreError: 8473:0:(cl_page.c:1026:cl_page_assume()) vvp-page@ffff880dbfdb9640(0:0:0) vm@ffffea0033482180 60000000000086d 4:0 ffff880f6107ad80 0 lru
2012-06-06 16:08:32 +0000 [4043242.419949] LustreError: 8473:0:(cl_page.c:1026:cl_page_assume()) lov-page@ffff880dbfdbdcf0
2012-06-06 16:08:32 +0000 [4043242.462875] LustreError: 8473:0:(cl_page.c:1026:cl_page_assume()) osc-page@ffff880f610795a8: 1< 0x845fed 2 0 - - - > 2< 0 0 51 0x0 0x400 | (null) ffff880e893b1fb8 ffff88176f4b3e80 ffffffffa1088200 ffff880f610795a8 > 3< - ffff880967a58000 0 0 0 > 4< 0 0 48 532799488 - | - - + - > 5< - - - - | 0 - - | 0 - ->
2012-06-06 16:08:32 +0000 [4043242.604818] LustreError: 8473:0:(cl_page.c:1026:cl_page_assume()) end page@ffff880f6107ad80
2012-06-06 16:08:32 +0000 [4043242.647677] LustreError: 8473:0:(cl_page.c:1026:cl_page_assume()) pg->cp_owner == NULL
2012-06-06 16:08:32 +0000 [4043242.688726] LustreError: 8473:0:(cl_page.c:1026:cl_page_assume()) ASSERTION( 0 ) failed:
2012-06-06 16:08:32 +0000 [4043242.731216] LustreError: 8473:0:(cl_page.c:1026:cl_page_assume()) LBUG
2012-06-06 16:08:32 +0000 [4043242.764574] Pid: 8473, comm: java
2012-06-06 16:08:32 +0000 [4043242.782718]
2012-06-06 16:08:32 +0000 [4043242.782720] Call Trace:
2012-06-06 16:08:32 +0000 [4043242.803973] [<ffffffffa0b77865>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
2012-06-06 16:08:32 +0000 [4043242.841227] [<ffffffffa0b77d97>] lbug_with_loc+0x47/0xc0 [libcfs]
2012-06-06 16:08:32 +0000 [4043242.872993] [<ffffffffa0d61b50>] cl_page_own0+0x0/0x2c0 [obdclass]
2012-06-06 16:08:32 +0000 [4043242.906060] [<ffffffffa1196726>] ll_prepare_write+0x86/0x170 [lustre]
2012-06-06 16:08:33 +0000 [4043242.940052] [<ffffffffa11aa8e8>] ll_write_begin+0x88/0x160 [lustre]
2012-06-06 16:08:33 +0000 [4043242.973265] [<ffffffffa11a51cb>] ? ll_getxattr+0xfb/0x440 [lustre]
2012-06-06 16:08:33 +0000 [4043243.005911] [<ffffffff810e75fe>] generic_file_buffered_write+0xfe/0x250
2012-06-06 16:08:33 +0000 [4043243.039902] [<ffffffff810ea1a0>] __generic_file_aio_write+0x230/0x470
2012-06-06 16:08:33 +0000 [4043243.073917] [<ffffffff810ea442>] generic_file_aio_write+0x62/0xd0
2012-06-06 16:08:33 +0000 [4043243.105326] [<ffffffffa11bb800>] vvp_io_write_start+0xb0/0x1e0 [lustre]
2012-06-06 16:08:33 +0000 [4043243.139984] [<ffffffffa0d6a1d2>] cl_io_start+0x72/0x100 [obdclass]
2012-06-06 16:08:33 +0000 [4043243.172847] [<ffffffffa0d6d774>] cl_io_loop+0xd4/0x160 [obdclass]
2012-06-06 16:08:33 +0000 [4043243.203854] [<ffffffffa1175d3e>] ll_file_io_generic+0x3be/0x4f0 [lustre]
2012-06-06 16:08:33 +0000 [4043243.238796] [<ffffffffa1175fa0>] ll_file_aio_write+0x130/0x1f0 [lustre]
2012-06-06 16:08:33 +0000 [4043243.272727] [<ffffffffa117634c>] ll_file_write+0x14c/0x250 [lustre]
2012-06-06 16:08:33 +0000 [4043243.306367] [<ffffffff811390a8>] vfs_write+0xc8/0x190
2012-06-06 16:08:33 +0000 [4043243.332757] [<ffffffff811398d1>] sys_write+0x51/0x90
2012-06-06 16:08:33 +0000 [4043243.359311] [<ffffffff8100bfc2>] system_call_fastpath+0x16/0x1b
2012-06-06 16:08:33 +0000 [4043243.389972]
2012-06-06 16:08:33 +0000 [4043243.399097] Kernel panic - not syncing: LBUG
2012-06-06 16:08:33 +0000 [4043243.421020] Pid: 8473, comm: java Tainted: G W 2.6.38.2-ts4 #11
2012-06-06 16:08:33 +0000 [4043243.455850] Call Trace:
2012-06-06 16:08:33 +0000 [4043243.468809] [<ffffffff8145a373>] ? panic+0x91/0x19c
2012-06-06 16:08:33 +0000 [4043243.494377] [<ffffffffa0b77dfb>] ? lbug_with_loc+0xab/0xc0 [libcfs]
2012-06-06 16:08:33 +0000 [4043243.527753] [<ffffffffa0d61b50>] ? cl_page_own0+0x0/0x2c0 [obdclass]
2012-06-06 16:08:33 +0000 [4043243.561570] [<ffffffffa1196726>] ? ll_prepare_write+0x86/0x170 [lustre]
2012-06-06 16:08:33 +0000 [4043243.595489] [<ffffffffa11aa8e8>] ? ll_write_begin+0x88/0x160 [lustre]
2012-06-06 16:08:33 +0000 [4043243.629850] [<ffffffffa11a51cb>] ? ll_getxattr+0xfb/0x440 [lustre]
2012-06-06 16:08:33 +0000 [4043243.661785] [<ffffffff810e75fe>] ? generic_file_buffered_write+0xfe/0x250
2012-06-06 16:08:33 +0000 [4043243.697719] [<ffffffff810ea1a0>] ? __generic_file_aio_write+0x230/0x470
2012-06-06 16:08:33 +0000 [4043243.734746] [<ffffffff810ea442>] ? generic_file_aio_write+0x62/0xd0
2012-06-06 16:08:33 +0000 [4043243.767215] [<ffffffffa11bb800>] ? vvp_io_write_start+0xb0/0x1e0 [lustre]
2012-06-06 16:08:33 +0000 [4043243.803208] [<ffffffffa0d6a1d2>] ? cl_io_start+0x72/0x100 [obdclass]
2012-06-06 16:08:33 +0000 [4043243.836585] [<ffffffffa0d6d774>] ? cl_io_loop+0xd4/0x160 [obdclass]
2012-06-06 16:08:33 +0000 [4043243.870706] [<ffffffffa1175d3e>] ? ll_file_io_generic+0x3be/0x4f0 [lustre]
2012-06-06 16:08:33 +0000 [4043243.907105] [<ffffffffa1175fa0>] ? ll_file_aio_write+0x130/0x1f0 [lustre]
2012-06-06 16:08:34 +0000 [4043243.942842] [<ffffffffa117634c>] ? ll_file_write+0x14c/0x250 [lustre]
2012-06-06 16:08:34 +0000 [4043243.977049] [<ffffffff811390a8>] ? vfs_write+0xc8/0x190
2012-06-06 16:08:34 +0000 [4043244.004041] [<ffffffff811398d1>] ? sys_write+0x51/0x90
2012-06-06 16:08:34 +0000 [4043244.031568] [<ffffffff8100bfc2>] ? system_call_fastpath+0x16/0x1b
2012-06-06 16:08:34 +0000 [4043244.063216] -----------[ cut here ]-----------
2012-06-06 16:08:34 +0000 [4043244.087602] WARNING: at arch/x86/kernel/smp.c:118 native_smp_send_reschedule+0x54/0x60()
2012-06-06 16:08:34 +0000 [4043244.129258] Hardware name: ProLiant BL460c G7
2012-06-06 16:08:34 +0000 [4043244.151613] Modules linked in: lmv mgc lustre lov osc mdc fid fld ksocklnd ptlrpc obdclass lnet lvfs libcfs parport_pc ppdev 8021q garp bridge stp llc nfsd netconsole configfs nfs lockd nfs_acl auth_rpcgss sunrpc dm_crypt dm_mod crc32c ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi iptable_filter ip_tables x_tables hpwdt psmouse be2net joydev hpilo evdev mac_hid serio_raw rtc_cmos rtc_core rtc_lib parport loop tcp_scalable fuse virtio_blk virtio virtio_ring xenfs ext4 mbcache jbd2 xfs exportfs raid1 usbhid mptspi mptsas mptscsih mptbase mpt2sas raid_class arcmsr aic94xx libsas libata scsi_transport_sas aic7xxx aic79xx scsi_transport_spi megaraid_sas cciss sg sd_mod hpsa ehci_hcd scsi_mod uhci_hcd [last unloaded: libcfs]
2012-06-06 16:08:34 +0000 [4043244.501423] Pid: 15289, comm: ptlrpcd_6 Tainted: G W 2.6.38.2-ts4 #11
2012-06-06 16:08:34 +0000 [4043244.540816] Call Trace:
2012-06-06 16:08:34 +0000 [4043244.553799] [<ffffffff8105d10f>] ? warn_slowpath_common+0x7f/0xc0
2012-06-06 16:08:34 +0000 [4043244.585974] [<ffffffff8105d16a>] ? warn_slowpath_null+0x1a/0x20
2012-06-06 16:08:34 +0000 [4043244.616810] [<ffffffff81029c24>] ? native_smp_send_reschedule+0x54/0x60
2012-06-06 16:08:34 +0000 [4043244.651789] [<ffffffff81045f06>] ? resched_task+0x76/0x90
2012-06-06 16:08:34 +0000 [4043244.679720] [<ffffffff81056465>] ? check_preempt_wakeup+0x1b5/0x280
2012-06-06 16:08:34 +0000 [4043244.714069] [<ffffffff81045fc4>] ? check_preempt_curr+0x84/0xa0
2012-06-06 16:08:34 +0000 [4043244.745025] [<ffffffff81055ebb>] ? try_to_wake_up+0x7b/0x410
2012-06-06 16:08:34 +0000 [4043244.775300] [<ffffffff81056262>] ? default_wake_function+0x12/0x20
2012-06-06 16:08:34 +0000 [4043244.808168] [<ffffffff8107e046>] ? autoremove_wake_function+0x16/0x40
2012-06-06 16:08:34 +0000 [4043244.841761] [<ffffffff810455c9>] ? __wake_up_common+0x59/0x90
2012-06-06 16:08:34 +0000 [4043244.873316] [<ffffffff8104d998>] ? __wake_up+0x48/0x70
2012-06-06 16:08:34 +0000 [4043244.900189] [<ffffffffa0b7834a>] ? cfs_waitq_signal+0x1a/0x20 [libcfs]
2012-06-06 16:08:35 +0000 [4043244.935008] [<ffffffffa1012227>] ? ksocknal_queue_tx_locked+0x277/0x540 [ksocklnd]
2012-06-06 16:08:35 +0000 [4043244.973972] [<ffffffffa100d033>] ? ksocknal_find_conn_locked+0xa3/0x230 [ksocklnd]
2012-06-06 16:08:35 +0000 [4043245.013276] [<ffffffffa101263b>] ? ksocknal_launch_packet+0x14b/0x350 [ksocklnd]
2012-06-06 16:08:35 +0000 [4043245.053190] [<ffffffffa10129be>] ? ksocknal_send+0x17e/0x410 [ksocklnd]
2012-06-06 16:08:35 +0000 [4043245.087409] [<ffffffffa0cce12b>] ? lnet_ni_send+0x4b/0x100 [lnet]
2012-06-06 16:08:35 +0000 [4043245.119743] [<ffffffffa0cd294b>] ? lnet_send+0x20b/0xa30 [lnet]
2012-06-06 16:08:35 +0000 [4043245.150531] [<ffffffffa0cce530>] ? lnet_prep_send+0x50/0xb0 [lnet]
2012-06-06 16:08:35 +0000 [4043245.183883] [<ffffffffa0cd3a49>] ? LNetPut+0x2a9/0x670 [lnet]
2012-06-06 16:08:35 +0000 [4043245.214255] [<ffffffffa0e9e4da>] ? ptl_send_buf+0x18a/0x440 [ptlrpc]
2012-06-06 16:08:35 +0000 [4043245.247512] [<ffffffffa0ea08a0>] ? ptl_send_rpc+0x4e0/0xb10 [ptlrpc]
2012-06-06 16:08:35 +0000 [4043245.280878] [<ffffffff8104bb3a>] ? finish_task_switch+0x4a/0x100
2012-06-06 16:08:35 +0000 [4043245.311703] [<ffffffffa0e97695>] ? ptlrpc_send_new_req+0x3e5/0x720 [ptlrpc]
2012-06-06 16:08:35 +0000 [4043245.348610] [<ffffffff8145d2bf>] ? _raw_spin_lock_irqsave+0x2f/0x40
2012-06-06 16:08:35 +0000 [4043245.381490] [<ffffffffa0e9a9a0>] ? ptlrpc_check_set+0x340/0x1750 [ptlrpc]
2012-06-06 16:08:35 +0000 [4043245.417485] [<ffffffff8106ca3a>] ? del_timer_sync+0x3a/0x60
2012-06-06 16:08:35 +0000 [4043245.447321] [<ffffffffa0ec4dcb>] ? ptlrpcd_check+0x52b/0x550 [ptlrpc]
2012-06-06 16:08:35 +0000 [4043245.480734] [<ffffffffa0ec50ab>] ? ptlrpcd+0x2bb/0x360 [ptlrpc]
2012-06-06 16:08:35 +0000 [4043245.514762] [<ffffffff81056250>] ? default_wake_function+0x0/0x20
2012-06-06 16:08:35 +0000 [4043245.546436] [<ffffffff8100cde4>] ? kernel_thread_helper+0x4/0x10
2012-06-06 16:08:35 +0000 [4043245.578542] [<ffffffffa0ec4df0>] ? ptlrpcd+0x0/0x360 [ptlrpc]
2012-06-06 16:08:35 +0000 [4043245.609487] [<ffffffff8100cde0>] ? kernel_thread_helper+0x0/0x10
2012-06-06 16:08:35 +0000 [4043245.640837] --[ end trace 70a7f3071bb3c3f8 ]--
|
|
Jinshan, could you help check why this ASSERT is not true on 2.6.38 kernel?
|
|
As Jinshan pointed out, it looks to be the same issue of LU-1421, the fix is at http://review.whamcloud.com/#change,3027. Roger, could you apply this patch and try again?
|
|
Customer reports:
We have been running with the latest patch for several days with no problems other than the old slowpath warning:
609631.154485] -----------[ cut here ]-----------
[609631.154499] WARNING: at fs/libfs.c:363 simple_setattr+0x99/0xb0()
[609631.154502] Hardware name: ProLiant BL460c G7
[609631.154504] Modules linked in: lmv mgc lustre lov osc mdc fid fld ksocklnd ptlrpc obdclass lnet lvfs libcfs parport_pc ppdev 8021q garp bridge stp llc nfsd nfs lockd nfs_acl auth_rpcgss sunrpc netconsole configfs dm_crypt dm_mod crc32c ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi iptable_filter ip_tables x_tables parport be2net psmouse evdev hpilo rtc_cmos joydev hpwdt serio_raw mac_hid loop rtc_core rtc_lib tcp_scalable fuse virtio_blk virtio virtio_ring xenfs ext4 mbcache jbd2 usbhid xfs exportfs raid1 mptspi mptsas mptscsih mptbase mpt2sas raid_class arcmsr aic94xx libsas libata scsi_transport_sas aic7xxx aic79xx scsi_transport_spi megaraid_sas cciss sd_mod sg hpsa scsi_mod ehci_hcd uhci_hcd [last unloaded: libcfs]
[609631.154578] Pid: 19765, comm: java Not tainted 2.6.38.2-ts4 #11
[609631.154580] Call Trace:
[609631.154588] [<ffffffff8105d10f>] ? warn_slowpath_common+0x7f/0xc0
[609631.154592] [<ffffffff8105d16a>] ? warn_slowpath_null+0x1a/0x20
[609631.154596] [<ffffffff8115bea9>] ? simple_setattr+0x99/0xb0
[609631.154632] [<ffffffffa10f2cd6>] ? ll_md_setattr+0x3e6/0x840 [lustre]
[609631.154652] [<ffffffffa10f3394>] ? ll_setattr_raw+0x264/0xe40 [lustre]
[609631.154672] [<ffffffffa10f3fcd>] ? ll_setattr+0x5d/0x100 [lustre]
[609631.154677] [<ffffffff81153761>] ? notify_change+0x161/0x2c0
[609631.154682] [<ffffffff811383d1>] ? do_truncate+0x61/0x90
[609631.154687] [<ffffffff811beeec>] ? security_inode_permission+0x1c/0x30
[609631.154692] [<ffffffff81144868>] ? finish_open+0x138/0x1b0
[609631.154696] [<ffffffff81146003>] ? do_last+0x83/0x360
[609631.154699] [<ffffffff81148706>] ? do_filp_open+0x3d6/0x830
[609631.154704] [<ffffffff8110bc27>] ? handle_mm_fault+0x157/0x250
[609631.154708] [<ffffffff8115493a>] ? alloc_fd+0x10a/0x150
[609631.154713] [<ffffffff811373a9>] ? do_sys_open+0x69/0x110
[609631.154717] [<ffffffff81137490>] ? sys_open+0x20/0x30
[609631.154722] [<ffffffff8100bfc2>] ? system_call_fastpath+0x16/0x1b
[609631.154725] --[ end trace e84ad085cd1d9abc ]--
Question: Is the best thing to do for this to lower the number of OST threads, as documented on the Lustre manual?
|
|
This is just kernel warning which is a bit excessive, and it has nothing to do with real IO performance. Lustre uses a kernel exported function simple_setattr(), which is originally for simple filesystem (which doesn't implement truncate), so it gives a warning, but there is no real problem.
|
Generated at Sat Feb 10 01:15:41 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
20120606-netconsole.tbz2
Reproduce.java