From mboxrd@z Thu Jan 1 00:00:00 1970 From: "ISHIKAWA,chiaki" Subject: Re: Hung CIFS driver Date: Sun, 10 Nov 2013 13:40:01 +0900 Message-ID: <527F0E21.603@yk.rim.or.jp> References: <527BAFC6.5010600@yk.rim.or.jp> <20131107110353.6d203196@tlielax.poochiereds.net> <527BC9C9.5080502@yk.rim.or.jp> <527D1ABD.3080404@yk.rim.or.jp> <527D2255.1070709@yk.rim.or.jp> <20131109065826.481ff52c@tlielax.poochiereds.net> Mime-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Cc: "linux-cifs-u79uwXL29TY76Z2rM5mHXA@public.gmane.org" To: Jeff Layton Return-path: In-Reply-To: <20131109065826.481ff52c-9yPaYZwiELC+kQycOl6kW4xkIHaj4LzF@public.gmane.org> Sender: linux-cifs-owner-u79uwXL29TY76Z2rM5mHXA@public.gmane.org List-ID: (2013/11/09 20:58), Jeff Layton wrote: > On Sat, 09 Nov 2013 02:41:41 +0900 > "ISHIKAWA,chiaki" wrote: > >> (2013/11/09 2:09), ISHIKAWA,chiaki wrote: >>> >>> In my next e-mail, I will report that >>> under Debian GNU/Linux 64bits, the CIFS driver >>> (uname -r shows 3.10-3-amd64) >>> can get hung, after a network error simulation by disabling >>> network interface and enabling again. >>> CIFS connection is reset, but a process gets stuck in I/O state >>> ("D" in ps output), and cannot be killed. >>> >> >> System: Debian GNU/Linux 64-bits running in a VMPlayer hosted on Win7. >> >> Remote host: Win7 (the host) >> >> Test: CIFS-share is mounted >> >> mount.cifs //192.168.0.112/L-temp /tmp/L-temp/ -o username=myid,noperm >> >> and under that mounted directory, the following test is performed. >> >> /tmp/L-temp is where CIFS-share is mounted. >> >> TEST SCRIPT: >> Below, >> |cp-test| is a program that copies bytes from a file to the other using >> read/write system calls. (I can post a source on request.) >> >> The test script is this: >> >> # big-file is a 26+MiB file. >> TDIR=/tmp/L-temp # changed to suit the system layout. >> while true >> do >> # t1=`create a temporary file name` >> t1=`mktemp $TDIR/1111XXXX` >> t2=`mktemp $TDIR/2222XXXX` >> t3=`mktemp $TDIR/3333XXXX` >> >> # big-file is a 26+MiB file. >> ./cp-test big-file ${t1} >> sleep 2 >> ./cp-test ${t1} ${t2} >> sleep 2 >> ./cp-test ${t2} ${t3} >> sleep 4 >> rm -f ${t1} ${t2} ${t3} >> sleep 2 >> done >> >> The other side: CIFS share is on Windows 7. >> I tried the remedies discussed in >> https://wiki.archlinux.org/index.php/Samba/Troubleshooting >> and in a few other places >> to remedy the error ("cannot allocate memory" due to non-paged resource >> allocation failure on Win7, and subsequent mount failure on linux side. >> >> Symptom: after a few tests of network failures simulated by >> disabling and enabling network interface of the VMPlayer, >> I noticed an incarnation of the program ./cp-test got stuck >> in "D" state, and could not be interrupted (^C) at all. >> I mounted CIFS-share with default option and so "soft" should be in effect. >> >> Since this happened already after a few tests were performed, >> I cannot exclude the possibility of screwed up Windows7 host, but even >> after a full day, >> I still cannot run "ls -lR" without getting the it hung (I cannot >> interrupt it with >> ^C). >> >> On the remote side, in Win7 system log, I see about the time the problem >> started >> (24 hours ago or so) that windows was complaining that >> >> The system could not allocate 983 work items in 60 seconds >> The system could not allocate 983 work items in 60 seconds >> etc. >> (my translation : I am using Japanese windows and so not sure what >> the English windows would show.) >> >> Now after 24 hours, I don't see it any more even when local "ls -lR" >> gets hung. I just tested. >> So it now becomes pure local issue. The driver gets hung somewhere >> without accessing the >> remote server at all. (Right, I see not much network traffic.) >> >> Here is the dmesg output : I only copied the last part of the output >> and threw away unrelated messages (unrelated, I hope). >> >> [133221.834132] FS-Cache: Netfs 'cifs' registered for caching >> [133221.834292] Key type cifs.spnego registered >> [133221.834322] Key type cifs.idmap registered >> [133221.966838] Status code returned 0xc000006d NT_STATUS_LOGON_FAILURE >> [133221.966846] CIFS VFS: Send error in SessSetup = -13 >> [133221.967211] CIFS VFS: cifs_mount failed w/return code = -13 >> [133331.808616] CIFS VFS: Error -104 sending data on socket to server >> [133331.808644] CIFS VFS: Error -32 sending data on socket to server >> >> [ lots of same messages (-32)...] >> >> [133331.809348] CIFS VFS: Error -32 sending data on socket to server >> >> **** Here I simulated the network error again **** >> > > $ grep 32 /usr/include/asm-generic/errno-base.h > #define EPIPE 32 /* Broken pipe */ > > ...this comes from the socket layer. > I see. >> [133566.580607] e1000: eth0 NIC Link is Down >> [133566.580722] e1000 0000:02:01.0 eth0: Reset adapter >> [133604.856771] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow >> Control: None >> >> **** Somehow CIFS in this version of linux seems to respond >> only after 120 seconds timeout. I thought there was 15 seconds >> timeout. **** >> >> [133690.810481] CIFS VFS: Server 192.168.0.112 has not responded in 120 >> seconds. Reconnecting... > > The cifs code attempts to send a SMB echo command (sort of like a ping > at the SMB layer) to the server every 60s. If the server doesn't > respond to two of them, the connection is reestablished. > >> [133929.781446] e1000: eth0 NIC Link is Down >> [133929.781621] e1000 0000:02:01.0 eth0: Reset adapter >> [133957.933636] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow >> Control: None >> [134054.949640] CIFS VFS: Server 192.168.0.112 has not responded in 120 >> seconds. Reconnecting... >> >> **** Obviously a read/write routine gets stuck more than 120 seconds. >> CIFS is being remounted after 120 seconds, but remount took more >> than a few seconds, I guess. So 120+ seconds hung for the >> stucked task/process **** >> > > It depends on what you mean by "routine" here. A read or write system > call may mean more than one SMB being transmitted on the wire. But it > really looks like you're having communications problems with the server. So a communicatin layer problem may have caused the SMB/CIFS layer to get stuck (?) > >> [134251.478654] INFO: task kworker/0:166:17092 blocked for more than 120 >> seconds. >> [134251.478659] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134251.478661] kworker/0:166 D ffff88028b613f40 0 17092 2 >> 0x00000000 >> [134251.478694] Workqueue: cifsiod cifs_oplock_break [cifs] >> [134251.478697] ffff8800a3c54100 0000000000000046 ffffffff81613400 >> 0000000000013f40 >> [134251.478703] ffff88005e8a1fd8 ffff88005e8a1fd8 ffff8800a3c54100 >> ffff88028b613f40 >> [134251.478706] ffff8800a3c54100 ffff88005e8a1d28 ffffffff810c051f >> 0000000000000002 >> [134251.478709] Call Trace: >> [134251.478781] [] ? __lock_page+0x61/0x61 >> [134251.478820] [] ? io_schedule+0x54/0x69 >> [134251.478824] [] ? sleep_on_page+0x5/0x8 >> [134251.478827] [] ? __wait_on_bit+0x3b/0x6e >> [134251.478829] [] ? wait_on_page_bit+0x69/0x6e >> [134251.478851] [] ? autoremove_wake_function+0x2a/0x2a >> [134251.478854] [] ? filemap_fdatawait_range+0x65/0xfa >> [134251.478860] [] ? cifs_oplock_break+0xd5/0x21d [cifs] >> [134251.478865] [] ? finish_task_switch+0x81/0xaa >> [134251.478871] [] ? process_one_work+0x18b/0x28c >> [134251.478873] [] ? worker_thread+0x121/0x1e7 >> [134251.478876] [] ? rescuer_thread+0x265/0x265 >> [134251.478878] [] ? kthread+0x7d/0x85 >> [134251.478881] [] ? __kthread_parkme+0x59/0x59 >> [134251.478885] [] ? ret_from_fork+0x7c/0xb0 >> [134251.478887] [] ? __kthread_parkme+0x59/0x59 >> [134251.478895] INFO: task pool:17993 blocked for more than 120 seconds. >> [134251.478897] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134251.478898] pool D ffff88028b613f40 0 17993 5142 >> 0x00000000 >> [134251.478901] ffff88027cbe6780 0000000000000082 ffffffff81613400 >> 0000000000013f40 >> [134251.478904] ffff880221259fd8 ffff880221259fd8 ffff88027cbe6780 >> ffff88028b613f40 >> [134251.478906] ffff88027cbe6780 ffff880221259bc0 ffffffff810c051f >> 0000000000000002 >> [134251.478909] Call Trace: >> [134251.478911] [] ? __lock_page+0x61/0x61 >> [134251.478914] [] ? io_schedule+0x54/0x69 >> [134251.478916] [] ? sleep_on_page+0x5/0x8 >> [134251.478918] [] ? __wait_on_bit+0x3b/0x6e >> [134251.478920] [] ? wait_on_page_bit+0x69/0x6e >> [134251.478922] [] ? autoremove_wake_function+0x2a/0x2a >> [134251.478987] [] ? >> invalidate_inode_pages2_range+0x94/0x226 >> [134251.478995] [] ? >> cifs_invalidate_mapping+0x22/0x51 [cifs] >> [134251.479000] [] ? cifs_d_revalidate+0x17/0x88 [cifs] >> [134251.479022] [] ? lookup_fast+0x17f/0x213 >> [134251.479026] [] ? walk_component+0x33/0x1a2 >> [134251.479029] [] ? path_lookupat+0x8e/0x293 >> [134251.479034] [] ? kmem_cache_alloc+0x8c/0xfd >> [134251.479037] [] ? filename_lookup+0x1f/0x73 >> [134251.479054] [] ? user_path_at_empty+0x6f/0xa6 >> [134251.479064] [] ? do_futex+0xd1/0x7b5 >> [134251.479066] [] ? vfs_fstatat+0x3e/0x8b >> [134251.479069] [] ? SYSC_newlstat+0x10/0x29 >> [134251.479072] [] ? system_call_fastpath+0x16/0x1b >> [134251.479074] INFO: task pool:18378 blocked for more than 120 seconds. >> [134251.479076] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134251.479077] pool D ffff88028b633f40 0 18378 5142 >> 0x00000000 >> [134251.479079] ffff88010cc2c840 0000000000000082 ffff880281179780 >> 0000000000013f40 >> [134251.479082] ffff88024678bfd8 ffff88024678bfd8 ffff88010cc2c840 >> ffff88028b633f40 >> [134251.479084] ffff88010cc2c840 ffff88024678bbc0 0000000000000002 >> ffffffff810c051f >> [134251.479087] Call Trace: >> [134251.479089] [] ? __lock_page+0x61/0x61 >> [134251.479092] [] ? io_schedule+0x54/0x69 >> [134251.479094] [] ? sleep_on_page+0x5/0x8 >> [134251.479096] [] ? __wait_on_bit_lock+0x3a/0x7e >> [134251.479098] [] ? __lock_page+0x5c/0x61 >> [134251.479101] [] ? autoremove_wake_function+0x2a/0x2a >> [134251.479105] [] ? >> invalidate_inode_pages2_range+0x6a/0x226 >> [134251.479111] [] ? >> cifs_invalidate_mapping+0x22/0x51 [cifs] >> [134251.479116] [] ? cifs_d_revalidate+0x17/0x88 [cifs] >> [134251.479119] [] ? lookup_fast+0x17f/0x213 >> [134251.479122] [] ? walk_component+0x33/0x1a2 >> [134251.479125] [] ? path_lookupat+0x8e/0x293 >> [134251.479128] [] ? kmem_cache_alloc+0x8c/0xfd >> [134251.479131] [] ? filename_lookup+0x1f/0x73 >> [134251.479133] [] ? user_path_at_empty+0x6f/0xa6 >> [134251.479136] [] ? ____cache_alloc+0x1d3/0x290 >> [134251.479138] [] ? vfs_fstatat+0x3e/0x8b >> [134251.479141] [] ? __call_rcu.constprop.51+0xc2/0x1c6 >> [134251.479143] [] ? SYSC_newlstat+0x10/0x29 >> [134251.479147] [] ? SyS_prctl+0x104/0x32f >> [134251.479149] [] ? system_call_fastpath+0x16/0x1b >> [134251.479151] INFO: task pool:18384 blocked for more than 120 seconds. >> [134251.479153] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134251.479154] pool D ffff88028b613f40 0 18384 5142 >> 0x00000000 >> [134251.479156] ffff88027c9c8800 0000000000000082 ffffffff81613400 >> 0000000000013f40 >> [134251.479159] ffff88024267dfd8 ffff88024267dfd8 ffff88027c9c8800 >> ffff88028b613f40 >> [134251.479161] ffff88027c9c8800 ffff88024267dbc0 0000000000000002 >> ffffffff810c051f >> [134251.479163] Call Trace: >> [134251.479166] [] ? __lock_page+0x61/0x61 >> [134251.479168] [] ? io_schedule+0x54/0x69 >> [134251.479170] [] ? sleep_on_page+0x5/0x8 >> [134251.479172] [] ? __wait_on_bit_lock+0x3a/0x7e >> [134251.479174] [] ? __lock_page+0x5c/0x61 >> [134251.479177] [] ? autoremove_wake_function+0x2a/0x2a >> [134251.479179] [] ? >> invalidate_inode_pages2_range+0x6a/0x226 >> [134251.479184] [] ? >> cifs_invalidate_mapping+0x22/0x51 [cifs] >> [134251.479189] [] ? cifs_d_revalidate+0x17/0x88 [cifs] >> [134251.479192] [] ? lookup_fast+0x17f/0x213 >> [134251.479195] [] ? walk_component+0x33/0x1a2 >> [134251.479197] [] ? path_lookupat+0x8e/0x293 >> [134251.479200] [] ? kmem_cache_alloc+0x8c/0xfd >> [134251.479203] [] ? filename_lookup+0x1f/0x73 >> [134251.479205] [] ? user_path_at_empty+0x6f/0xa6 >> [134251.479208] [] ? __wake_up_sync_key+0x3d/0x55 >> [134251.479211] [] ? kmem_cache_alloc+0x8c/0xfd >> [134251.479213] [] ? vfs_fstatat+0x3e/0x8b >> [134251.479215] [] ? __call_rcu.constprop.51+0xc2/0x1c6 >> [134251.479217] [] ? SYSC_newlstat+0x10/0x29 >> [134251.479220] [] ? SyS_prctl+0x104/0x32f >> [134251.479223] [] ? system_call_fastpath+0x16/0x1b >> [134251.479225] INFO: task pool:18385 blocked for more than 120 seconds. >> [134251.479226] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134251.479227] pool D ffff88028b613f40 0 18385 5142 >> 0x00000000 >> [134251.479229] ffff8802427e9080 0000000000000082 ffffffff81613400 >> 0000000000013f40 >> [134251.479232] ffff88024674ffd8 ffff88024674ffd8 ffff8802427e9080 >> ffff88028b613f40 >> [134251.479234] ffff8802427e9080 ffff88024674fda8 ffffffff810c051f >> 0000000000000002 >> [134251.479236] Call Trace: >> [134251.479239] [] ? __lock_page+0x61/0x61 >> [134251.479241] [] ? io_schedule+0x54/0x69 >> [134251.479243] [] ? sleep_on_page+0x5/0x8 >> [134251.479245] [] ? __wait_on_bit+0x3b/0x6e >> [134251.479247] [] ? wait_on_page_bit+0x69/0x6e >> [134251.479250] [] ? autoremove_wake_function+0x2a/0x2a >> [134251.479252] [] ? filemap_fdatawait_range+0x65/0xfa >> [134251.479259] [] ? cifs_getattr+0x45/0xe6 [cifs] >> [134251.479262] [] ? vfs_fstatat+0x4f/0x8b >> [134251.479264] [] ? SYSC_newlstat+0x10/0x29 >> [134251.479267] [] ? SyS_prctl+0x104/0x32f >> [134251.479270] [] ? system_call_fastpath+0x16/0x1b >> [134251.479273] INFO: task cp-test:17969 blocked for more than 120 seconds. >> [134251.479275] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134251.479276] cp-test D ffff88028b613f40 0 17969 16775 >> 0x00000000 >> [134251.479278] ffff880221270040 0000000000000086 ffffffff81613400 >> 0000000000013f40 >> [134251.479281] ffff88010cc85fd8 ffff88010cc85fd8 ffff880221270040 >> ffff88028b613f40 >> [134251.479283] ffff880221270040 ffff88010cc85e38 ffffffff810c051f >> 0000000000000002 >> [134251.479285] Call Trace: >> [134251.479288] [] ? __lock_page+0x61/0x61 >> [134251.479290] [] ? io_schedule+0x54/0x69 >> [134251.479292] [] ? sleep_on_page+0x5/0x8 >> [134251.479294] [] ? __wait_on_bit+0x3b/0x6e >> [134251.479296] [] ? wait_on_page_bit+0x69/0x6e >> [134251.479299] [] ? autoremove_wake_function+0x2a/0x2a >> [134251.479301] [] ? filemap_fdatawait_range+0x65/0xfa >> [134251.479304] [] ? filemap_write_and_wait+0x20/0x33 >> [134251.479309] [] ? cifs_flush+0x1d/0x4d [cifs] >> [134251.479329] [] ? filp_close+0x37/0x68 >> [134251.479333] [] ? SyS_close+0x1a/0x3c >> [134251.479335] [] ? system_call_fastpath+0x16/0x1b >> [134371.629437] INFO: task kworker/0:166:17092 blocked for more than 120 >> seconds. >> [134371.629442] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134371.629445] kworker/0:166 D ffff88028b613f40 0 17092 2 >> 0x00000000 >> [134371.629504] Workqueue: cifsiod cifs_oplock_break [cifs] >> [134371.629507] ffff8800a3c54100 0000000000000046 ffffffff81613400 >> 0000000000013f40 >> [134371.629511] ffff88005e8a1fd8 ffff88005e8a1fd8 ffff8800a3c54100 >> ffff88028b613f40 >> [134371.629515] ffff8800a3c54100 ffff88005e8a1d28 ffffffff810c051f >> 0000000000000002 >> [134371.629518] Call Trace: >> [134371.629526] [] ? __lock_page+0x61/0x61 >> [134371.629532] [] ? io_schedule+0x54/0x69 >> [134371.629535] [] ? sleep_on_page+0x5/0x8 >> [134371.629538] [] ? __wait_on_bit+0x3b/0x6e >> [134371.629541] [] ? wait_on_page_bit+0x69/0x6e >> [134371.629546] [] ? autoremove_wake_function+0x2a/0x2a >> [134371.629549] [] ? filemap_fdatawait_range+0x65/0xfa >> [134371.629557] [] ? cifs_oplock_break+0xd5/0x21d [cifs] >> [134371.629562] [] ? finish_task_switch+0x81/0xaa >> [134371.629566] [] ? process_one_work+0x18b/0x28c >> [134371.629570] [] ? worker_thread+0x121/0x1e7 >> [134371.629573] [] ? rescuer_thread+0x265/0x265 >> [134371.629576] [] ? kthread+0x7d/0x85 >> [134371.629579] [] ? __kthread_parkme+0x59/0x59 >> [134371.629583] [] ? ret_from_fork+0x7c/0xb0 >> [134371.629586] [] ? __kthread_parkme+0x59/0x59 >> [134371.629596] INFO: task pool:17993 blocked for more than 120 seconds. >> [134371.629598] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134371.629600] pool D ffff88028b613f40 0 17993 5142 >> 0x00000000 >> [134371.629603] ffff88027cbe6780 0000000000000082 ffffffff81613400 >> 0000000000013f40 >> [134371.629606] ffff880221259fd8 ffff880221259fd8 ffff88027cbe6780 >> ffff88028b613f40 >> [134371.629609] ffff88027cbe6780 ffff880221259bc0 ffffffff810c051f >> 0000000000000002 >> [134371.629613] Call Trace: >> [134371.629616] [] ? __lock_page+0x61/0x61 >> [134371.629619] [] ? io_schedule+0x54/0x69 >> [134371.629622] [] ? sleep_on_page+0x5/0x8 >> [134371.629625] [] ? __wait_on_bit+0x3b/0x6e >> [134371.629632] [] ? wait_on_page_bit+0x69/0x6e >> [134371.629636] [] ? autoremove_wake_function+0x2a/0x2a >> [134371.629641] [] ? >> invalidate_inode_pages2_range+0x94/0x226 >> [134371.629649] [] ? >> cifs_invalidate_mapping+0x22/0x51 [cifs] >> [134371.629656] [] ? cifs_d_revalidate+0x17/0x88 [cifs] >> [134371.629661] [] ? lookup_fast+0x17f/0x213 >> [134371.629664] [] ? walk_component+0x33/0x1a2 >> [134371.629668] [] ? path_lookupat+0x8e/0x293 >> [134371.629673] [] ? kmem_cache_alloc+0x8c/0xfd >> [134371.629677] [] ? filename_lookup+0x1f/0x73 >> [134371.629680] [] ? user_path_at_empty+0x6f/0xa6 >> [134371.629686] [] ? do_futex+0xd1/0x7b5 >> [134371.629689] [] ? vfs_fstatat+0x3e/0x8b >> [134371.629692] [] ? SYSC_newlstat+0x10/0x29 >> [134371.629696] [] ? system_call_fastpath+0x16/0x1b >> [134371.629699] INFO: task pool:18378 blocked for more than 120 seconds. >> [134371.629700] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134371.629702] pool D ffff88028b633f40 0 18378 5142 >> 0x00000000 >> [134371.629705] ffff88010cc2c840 0000000000000082 ffff880281179780 >> 0000000000013f40 >> [134371.629708] ffff88024678bfd8 ffff88024678bfd8 ffff88010cc2c840 >> ffff88028b633f40 >> [134371.629711] ffff88010cc2c840 ffff88024678bbc0 0000000000000002 >> ffffffff810c051f >> [134371.629715] Call Trace: >> [134371.629717] [] ? __lock_page+0x61/0x61 >> [134371.629721] [] ? io_schedule+0x54/0x69 >> [134371.629723] [] ? sleep_on_page+0x5/0x8 >> [134371.629727] [] ? __wait_on_bit_lock+0x3a/0x7e >> [134371.629729] [] ? __lock_page+0x5c/0x61 >> [134371.629732] [] ? autoremove_wake_function+0x2a/0x2a >> [134371.629736] [] ? >> invalidate_inode_pages2_range+0x6a/0x226 >> [134371.629743] [] ? >> cifs_invalidate_mapping+0x22/0x51 [cifs] >> [134371.629749] [] ? cifs_d_revalidate+0x17/0x88 [cifs] >> [134371.629753] [] ? lookup_fast+0x17f/0x213 >> [134371.629757] [] ? walk_component+0x33/0x1a2 >> [134371.629760] [] ? path_lookupat+0x8e/0x293 >> [134371.629764] [] ? kmem_cache_alloc+0x8c/0xfd >> [134371.629768] [] ? filename_lookup+0x1f/0x73 >> [134371.629770] [] ? user_path_at_empty+0x6f/0xa6 >> [134371.629775] [] ? ____cache_alloc+0x1d3/0x290 >> [134371.629777] [] ? vfs_fstatat+0x3e/0x8b >> [134371.629781] [] ? __call_rcu.constprop.51+0xc2/0x1c6 >> [134371.629784] [] ? SYSC_newlstat+0x10/0x29 >> [134371.629788] [] ? SyS_prctl+0x104/0x32f >> [134371.629792] [] ? system_call_fastpath+0x16/0x1b >> [134371.629794] INFO: task pool:18384 blocked for more than 120 seconds. >> [134371.629796] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" >> disables this message. >> [134371.629798] pool D ffff88028b613f40 0 18384 5142 >> 0x00000000 >> [134371.629801] ffff88027c9c8800 0000000000000082 ffffffff81613400 >> 0000000000013f40 >> [134371.629804] ffff88024267dfd8 ffff88024267dfd8 ffff88027c9c8800 >> ffff88028b613f40 >> [134371.629807] ffff88027c9c8800 ffff88024267dbc0 0000000000000002 >> ffffffff810c051f >> [134371.629811] Call Trace: >> [134371.629813] [] ? __lock_page+0x61/0x61 >> [134371.629817] [] ? io_schedule+0x54/0x69 >> [134371.629819] [] ? sleep_on_page+0x5/0x8 >> [134371.629822] [] ? __wait_on_bit_lock+0x3a/0x7e >> [134371.629825] [] ? __lock_page+0x5c/0x61 >> [134371.629828] [] ? autoremove_wake_function+0x2a/0x2a >> [134371.629831] [] ? >> invalidate_inode_pages2_range+0x6a/0x226 >> [134371.629838] [] ? >> cifs_invalidate_mapping+0x22/0x51 [cifs] >> [134371.629846] [] ? cifs_d_revalidate+0x17/0x88 [cifs] >> [134371.629850] [] ? lookup_fast+0x17f/0x213 >> [134371.629854] [] ? walk_component+0x33/0x1a2 >> [134371.629857] [] ? path_lookupat+0x8e/0x293 >> [134371.629861] [] ? kmem_cache_alloc+0x8c/0xfd >> [134371.629865] [] ? filename_lookup+0x1f/0x73 >> [134371.629868] [] ? user_path_at_empty+0x6f/0xa6 >> [134371.629871] [] ? __wake_up_sync_key+0x3d/0x55 >> [134371.629875] [] ? kmem_cache_alloc+0x8c/0xfd >> [134371.629878] [] ? vfs_fstatat+0x3e/0x8b >> [134371.629881] [] ? __call_rcu.constprop.51+0xc2/0x1c6 >> [134371.629884] [] ? SYSC_newlstat+0x10/0x29 >> [134371.629888] [] ? SyS_prctl+0x104/0x32f >> [134371.629891] [] ? system_call_fastpath+0x16/0x1b >> [184501.155185] CIFS VFS: Server 192.168.0.112 has not responded in 120 >> seconds. Reconnecting... >> >> **** But now after this, the test program copying a file from the other >> gets stuck in D state and cannot be killed. >> I think only reboot will remedy this situation. >> > > Most of these processes are stuck trying to lock a page to either > invalidate it, or to perform writeback. That implies that something else is holding the lock on that page. > I see. Now I realize there many lock/validate strings in the function names in the stack trace. >> Hope this helps. >> >> Even if this could be triggered by flakey windows 7 CIFS-share issues, >> I think it is worthwhile to make CIFS driver robust in such situations. >> > > Me too -- easier said than done ;) > Agreed. Just wade through the stack trace and figure out what is going on is difficult ;) >> I am keeping this linux running in this manner and so >> let me know if you need some runtime information which can be gleaned by >> some means (like system trace, etc.). Please advise how to obtain the >> information in that case (the particular command to obtain the desired >> value will be useful.) >> > > I think what's missing here is some information about what's actually > happening on the network when you try to recontact the server. > > When you bring the interface back up, does the client ever send a SYN > back to the server? If so, does the server respond? > OK, here is my TODO list: I will try to capture the packet using WireShark on the side of Win7 host. Oh wait, can I ping the host right now? Of course, it can. I understand that the suggestion about SYN is regarding the TCP socket (CIFS now uses TCP, I suppose) reestablishment. > Also, what is cifsd (the kernel thread that handles receives) doing at > this point? I'd expect it to be trying to reconnect to the server... > CIFS driver is inside the kernel, correct. I am not entirely sure how I can do this. Maybe I should use google to figure out how to debug kernel thread. > What kernel version is this too, btw? uname -r 3.10-3-amd64 It is 3.10.3 64bit. Chiaki Ishikawa