Client kernel warning when deleting large number of files

[dah...@gmail.com]

Hi-

I have an app which puts 15000 files in 256 directories on a server (which is running all the daemons, storage on a separate disk).

One client which is trying to remove them (in code using Node.js fs module).

Occasionally when I run the remove, one of the files just won't delete (I get EBUSY back). At the same time, syslog shows the following warning:

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431585] WARNING: CPU: 2 PID: 14175 at /build/buildd/linux-3.11.0/fs/inode.c:281 drop_nlink+0x3e/0x50()

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431589] Modules linked in: fhgfs(OF) fhgfs_client_opentk(OF) pci_stub vboxpci(OF) vboxnetadp(OF) vboxnetflt(OF) vboxdrv(OF) dm_crypt ib_iser rdma_cm ib_addr iw_cm ib_cm ib_sa ib_mad ib_core iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi parport_pc ppdev bnep rfcomm bluetooth x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm rt5390sta(POF) crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel aes_x86_64 lrw uvcvideo gf128mul glue_helper videobuf2_vmalloc videobuf2_memops videobuf2_core ablk_helper cryptd arc4 hp_wmi joydev sparse_keymap videodev rt2800pci rt2800lib rt2x00pci rt2x00mmio rt2x00lib mac80211 snd_hda_codec_hdmi snd_hda_codec_idt snd_hda_intel snd_hda_codec cfg80211 eeprom_93cx6 rtsx_pci_ms hp_accel memstick lpc_ich snd_hwdep snd_pcm snd_page_alloc snd_seq_midi snd_seq_midi_event snd_rawmidi crc_ccitt snd_seq snd_seq_device snd_timer snd nfsd psmouse microcode serio_raw soundcore mac_hid lis3lv02d mei_me input_polldev mei auth_rpcgss nfs_ac

Feb 24 21:19:55 david-hp-laptop kernel: l nfs lockd sunrpc binfmt_misc fscache lp parport rtsx_pci_sdmmc i915 i2c_algo_bit drm_kms_helper drm ahci libahci r8169 rtsx_pci mii video wmi [last unloaded: fhgfs_client_opentk]

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431732] CPU: 2 PID: 14175 Comm: node Tainted: PF       W  O 3.11.0-15-generic #25-Ubuntu

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431737] Hardware name: Hewlett-Packard HP Pavilion g6 Notebook PC/183F, BIOS F.16 10/09/2012

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431741]  0000000000000009 ffff880148dffda8 ffffffff816e7375 0000000000000000

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431747]  ffff880148dffde0 ffffffff81061dcd ffff8801767f4080 ffff8801006bd600

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431751]  0000000000000000 ffff8801a117e800 ffff880113673ed8 ffff880148dffdf0

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431756] Call Trace:

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431767]  [<ffffffff816e7375>] dump_stack+0x45/0x56

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431774]  [<ffffffff81061dcd>] warn_slowpath_common+0x7d/0xa0

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431780]  [<ffffffff81061eaa>] warn_slowpath_null+0x1a/0x20

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431785]  [<ffffffff811c0aae>] drop_nlink+0x3e/0x50

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431813]  [<ffffffffa09a2ea0>] FhgfsOps_unlink+0xf0/0x1f0 [fhgfs]

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431823]  [<ffffffff811b49e0>] vfs_unlink+0x90/0x100

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431831]  [<ffffffff811b6aa9>] do_unlinkat+0x229/0x260

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431839]  [<ffffffff811b65b9>] ? putname+0x29/0x40

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431847]  [<ffffffff811a649b>] ? do_sys_open+0x1bb/0x270

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431855]  [<ffffffff811b7666>] SyS_unlink+0x16/0x20

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431864]  [<ffffffff816f725d>] system_call_fastpath+0x1a/0x1f

Feb 24 21:19:55 david-hp-laptop kernel: [22994.431868] ---[ end trace 8cb289933d7118e7 ]---

Feb 24 21:19:55 david-hp-laptop kernel: [22994.447936] ------------[ cut here ]------------

I can remove the file from another process (using bash or Node.js) or if I kill the app and run it again then the new instance successfully removes the file. I'd have put it down to Node but when I saw the kernel warning above I wondered whether it was indicative of something in the FhGFS client module?

David 

[Christian Mohrbacher Fraunhofer ITWM]

Hi,
we are not aware of such a problem. To have a closer look and to see if we can find something, what version of FhGFS are you using?

Regards,
Christian

----------------ursprüngliche Nachricht-----------------
Von: dah...@gmail.com
An: fhgfs...@googlegroups.com
Datum: Tue, 25 Feb 2014 01:02:13 -0800 (PST)
-------------------------------------------------

> --
> You received this message because you are subscribed to the Google Groups
> "fhgfs-user" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to
> fhgfs-user+...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>

--

=======================================================
Christian Mohrbacher
Competence Center High Performance Computing
Institut fuer Techno- und Wirtschaftsmathematik (ITWM)
Fraunhofer-Platz 1

D-67663 Kaiserslautern
=======================================================
Tel.: (49) 631 31600 4425
Fax: (49) 631 31600 1099
E-Mail: christian....@itwm.fraunhofer.de
Internet: http://www.itwm.fraunhofer.de
=======================================================

[dah...@gmail.com]

2012.10.r13.debian7

Are there any extra debug options I can turn on?

[Sven Breuner]

Hi David,

dah...@gmail.com wrote on 02/26/2014 12:29 AM:
> 2012.10.r13.debian7
>
> Are there any extra debug options I can turn on?

you could set logLevel=5 in fhgfs-client.conf to get more log messages
or even add FHGFS_DEBUG=1 to buildArgs in
/etc/fhgfs/fhgfs-client-autobuild.conf to generate a client debug build
with more log messages.

Do you see anything suspicious in /etc/fhgfs/fhgfs-client.log or
/etc/fhgfs/fhgfs-meta.log when this happens?

I don't see a way in the fhgfs client's unlink method how it could call
drop_nlink (that we see in your trace) and return EBUSY together, so
your situation is really strange.

In general, a "create a lot of files in a lot of dirs and remove them
afterwards" test case is of course part of our standard release test
suite, so I assume if your issue is fhgfs-related, your case and access
pattern is somewhat more complex.
Can you provide more details on that, e.g. are some of the files still
open while they are being unlinked or is any other process accessing
these files while the unlink is running?

Best regards,
Sven Breuner
Fraunhofer

> On Tuesday, 25 February 2014 20:37:49 UTC, Christian Mohrbacher
> Fraunhofer ITWM wrote:
>
> Hi,
> we are not aware of such a problem. To have a closer look and to see
> if we can find something, what version of FhGFS are you using?
>
> Regards,
> Christian
>
> ----------------ursprüngliche Nachricht-----------------

> Von: dah...@gmail.com <javascript:>
> An: fhgfs...@googlegroups.com <javascript:>

> =======================================================
> Christian Mohrbacher
> Competence Center High Performance Computing
> Institut fuer Techno- und Wirtschaftsmathematik (ITWM)
> Fraunhofer-Platz 1
>
> D-67663 Kaiserslautern
> =======================================================
> Tel.: (49) 631 31600 4425
> Fax: (49) 631 31600 1099

> E-Mail: christian....@itwm.fraunhofer.de <javascript:>
> Internet: http://www.itwm.fraunhofer.de
> =======================================================
>

[dah...@gmail.com]

Hi Sven-

Yes, some of the files will be open (and flocked) when unlinked. Before unlinking them I also ftruncate them.

I've repro'd it with a short run at logLevel=3 but couldn't see anything in the logs. I'll try again at logLevel=5 and get back to you.

Thanks

David

[dah...@gmail.com]

This is the log message when I get an EBUSY:

(4) Feb26 22:43:17 *node(22265) [FhgfsOps_rename] >> Rename failed: Entry is in 

use fromDirID: 16FA6-530E5E18-4071 oldName: foo@s+1447094afae+m+32ca331b5b7a8f26

997a52c21962970b toDirID: 1706E-530E5E18-4071 newName: foo@s+1447094afae+m+32ca3

31b5b7a8f26997a52c21962970b EntryID: 17F1C-530E5E18-4071

I'm guessing this is because the file descriptor is still open when rename is called?

In this case, the drop_nlink stack is also put into syslog BUT when the rename is tried again after 1 second, it succeeds:

(4) Feb26 22:43:18 *node(22265) [FhgfsOps_rename] >> called. From: foo@s+1447094afae+m+32ca331b5b7a8f26997a52c21962970b; To: foo@s+1447094afae+m+32ca331b5b7a8f26997a52c21962970b

I wonder if there is a Node issue where it's holding file descriptors open for some time even after raising a 'finish' event. It's certainly free to do so. Sometimes it may either hold them open for a long time or maybe lose them for some reason.

But even so, I'm definitely see the drop_nlink stack when an EBUSY is returned.

David

[dah...@gmail.com]

So I just repro'd the EBUSY loop. What I'm seeing in this case is that instead of getting ENOTEMPTY when calling rmdir on a directory with files in it, EBUSY is returned instead. That causes me to miss this case and loop.

The fhgfs-client.log says:

(4) Feb26 23:21:08 *node(23619) [Remoting (rmdir)] >> RmDirResp error code: Entry is in use

Now, if I change my recursive delete code to treat EBUSY like ENOTEMPTY and remove the files in the directory then all is fine - I have no trouble deleting the files and then rmdir succeeds. 

Is there a case where EBUSY can be returned for rmdir instead of ENOTEMPTY?

(Btw I think the EBUSY for rename that I'm encountering too is as expected because I'm trying to rename too early before the file is closed so please ignore that). 

[Sven Breuner]

Hi David,

dah...@gmail.com wrote on 02/27/2014 12:26 AM:
> So I just repro'd the EBUSY loop. What I'm seeing in this case is that
> instead of getting ENOTEMPTY when calling rmdir on a directory with
> files in it, EBUSY is returned instead. That causes me to miss this case
> and loop.
>
> The fhgfs-client.log says:
>
> (4) Feb26 23:21:08 *node(23619) [Remoting (rmdir)] >> RmDirResp error
> code: Entry is in use

in general, it is allowed for a file system to return EBUSY on rmdir,
but from your description so far, I don't see how your workflow could
trigger this case, because in the trivial case, fhgfs returns the normal
ENOTEMPTY, e.g.:
$ mkdir /mnt/fhgfs/dir1
$ touch /mnt/fhgfs/dir1/file1
$ rmdir /mnt/fhgfs/dir1

=> ENOTEMPTY

More comments on your other mail below...

> On Wednesday, 26 February 2014 22:56:44 UTC, dah...@gmail.com wrote:
>
> This is the log message when I get an EBUSY:
>
> (4) Feb26 22:43:17 *node(22265) [FhgfsOps_rename] >> Rename failed:
> Entry is in
> use fromDirID: 16FA6-530E5E18-4071 oldName:
> foo@s+1447094afae+m+32ca331b5b7a8f26
> 997a52c21962970b toDirID: 1706E-530E5E18-4071 newName:
> foo@s+1447094afae+m+32ca3
> 31b5b7a8f26997a52c21962970b EntryID: 17F1C-530E5E18-4071
>
> I'm guessing this is because the file descriptor is still open when
> rename is called?
>
> In this case, the drop_nlink stack is also put into syslog BUT when
> the rename is tried again after 1 second, it succeeds:

The drop_nlink stack from your first mail was coming from an unlink, not
from a rename. Are you sure that this time the warning is coming from a
rename?

I tried to reproduce your case from the description that I had so far,
but wasn't able to:
shell1$ echo abc > /mnt/fhgfs/dir1/file1
shell1$ less /mnt/fhgfs/dir1/file1 # to keep the file open
shell2$ rm /mnt/fhgfs/dir1/file1 # unlink open file
shell1$ "quit less"

=> no error and no drop_nlink warning in dmesg.

Can you provide a simple script or a small program that triggers the
drop_nlink warning?

[dah...@gmail.com]

Hi Sven-

in general, it is allowed for a file system to return EBUSY on rmdir,
but from your description so far, I don't see how your workflow could
trigger this case, because in the trivial case, fhgfs returns the normal
ENOTEMPTY, e.g.:
$ mkdir /mnt/fhgfs/dir1
$ touch /mnt/fhgfs/dir1/file1
$ rmdir /mnt/fhgfs/dir1

=> ENOTEMPTY

It is really strange as even when the original process exits, subsequent processes get EBUSY too. 

However, I found another place where I wasn't waiting for fd close before renaming a file and now the test runs without any EBUSY errors.

 

I tried to reproduce your case from the description that I had so far,
but wasn't able to:
shell1$ echo abc > /mnt/fhgfs/dir1/file1
shell1$ less /mnt/fhgfs/dir1/file1 # to keep the file open
shell2$ rm /mnt/fhgfs/dir1/file1 # unlink open file
shell1$ "quit less"

=> no error and no drop_nlink warning in dmesg.

Can you provide a simple script or a small program that triggers the
drop_nlink warning?

That might be difficult since it's in quite a large set of tests which I haven't split up yet. 

To be honest, everything is actually working fine now. Certainly far better than I found with NFS4 (stuck call in kernel, missed updates), Gluster (spinning daemon, confusing cache semantics), CIFS (no locking without oplocks which I had to disable to get cache coherence working) and OCFS2/iSCSI (runbelievably slow unlink performance). I haven't tried CephFS yet but I'm certainly impressed with FhGFS.

David

[Sven Breuner]

Hi David,

dah...@gmail.com wrote on 02/27/2014 10:05 PM:
> [...] but I'm certainly impressed with FhGFS.

thanks! Always good to hear such things :)