zfs diff support

[b333z]

To be able to see a diff across snapshots of a massive filesystem in a matter of seconds will be a great thing.

Thanks to all the great work on the snapshot dirs issue #173, once the snapshot code is finalized, as far as I can tell we will be close to getting the zfs diff command operational.

After compiling up rohan-puri's snapshot branch we get:

b15 zfs # zfs diff data@snap3 data@snap4
Cannot stat /data/.zfs/shares/: unable to generate diffs

But after removing the code from libzfs_diff.c that checks for the '.zfs/share' directory:

  diff --git a/lib/libzfs/libzfs_diff.c b/lib/libzfs/libzfs_diff.c
  index 8140a70..c00ca75 100644
  --- a/lib/libzfs/libzfs_diff.c
  +++ b/lib/libzfs/libzfs_diff.c
  @@ -739,8 +739,8 @@ setup_differ_info(zfs_handle_t *zhp, const char *fromsnap,
      if (get_mountpoints(di) != 0)
          return (-1);

  -       if (find_shares_object(di) != 0)
  -               return (-1);
  +       //if (find_shares_object(di) != 0)
  +       //      return (-1);

      return (0);
  }

I was able to see a simple diff in operation:

b15 ~ # zfs diff data@snap3 data@snap4
M       /data/
+       /data/fstab
b15 ~ # 

( for comparison )

b15 ~ # diff -r /data/.zfs/snapshot/snap3 /data/.zfs/snapshot/snap4 
    Only in /data/.zfs/snapshot/snap4: fstab

Would be good to investigate the diff command's requirements including the .zfs/share directory, so that once the snapshot code is finalized we can get the diff command working correctly.

I will spent some time attempting to understand it via the source code, but anyone got and tips/starting points about what the .zfs/share directory is there for other than to adjust smb acl's and why the libzfs_diff.c file wants to look at it?

[b333z]

From an initial look, my feeling is that the reason that it does a stat64 on the /.zfs/shares/ directory in order to collect its inode and place it in differ_info.shares, is so that directory does not get included in the diff.

From what I can tell differ_info.shares is then used in functions write_inuse_diffs_one() and write_free_diffs() to bail early if the current object is the /.zfs/shares/ directory.

If this is the case this would leave me to believe that because we currently don't have a /.zfs/shares/ directory that for now we could skip the find_shares_object(di) call as long as differ_info->shares is initialised to a value that would never be found as a inode in a dataset ( would 0 be the correct value for this purpose )? Or would we remove the bits entirely?

Does this sound like I'm on the right track, if so what would be then best way to move forward, will zfsonlinux have a shares directory in the the future?

[b333z]

b15 system # zfs diff -F system@test2
M       /       /system/
R       F       /system/test1.txt -> /system/test2.txt
-       F       /system/test3.txt
+       /       /system/logrotate.d
+       F       /system/logrotate.d/openrc
+       F       /system/logrotate.d/rsyncd
+       F       /system/logrotate.d/elog-save-summary
+       F       /system/logrotate.d/._cfg0000_elog-save-summary
+       F       /system/logrotate.d/syslog-ng

[behlendorf]

Yes, ZoL will have a .zfs/shares directory in the future. In fact the updated patch in #173 does add it, although it's currently non-functional. Still that might be enough to get your past this problem. If you get a chance could you try the updated patch and see if 'zfs diff' is happy. It may not be, the .zfs/shares heirarchy hasn't seen much testing.

[b333z]

Cheers Brian, gave the zfs diff command a test against your zfs snapshot branch behlendorf/zfs@6e2c435e18 and zfsonlinux spl master branch openzfs/spl@93806f58a6, this is looking good, now getting past the "Cannot stat /data/.zfs/shares/: unable to generate diffs" error and is displaying the diff, but then the process hangs.

I rebooted and replicated the issue running it via strace: strace zfs diff data@empty and I found it seems to hang on the close() of the /dev/zfs file handle.

Once this has happened any command that requires /dev/zfs will hang when trying to open() a file handle to it.

The kernel itself seems happy and I can traverse the zfs file systems as normal, seems just userland access to /dev/zfs breaks. dmesg shows no errors.

Here is a gist of the strace: https://gist.github.com/1475854

But here is the last few lines:

open("/dev/zfs", O_RDWR)                = 8
ioctl(5, 0x5a3a, 0x7fffcfce03c0)        = 0
fstat(6, {st_mode=S_IFREG|0644, st_size=852, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc9a7673000
lseek(6, 0, SEEK_SET)                   = 0
read(6, "rootfs / rootfs rw 0 0\nproc /pro"..., 4096) = 852
stat("/data/.zfs/shares/", {st_mode=S_IFDIR|0555, st_size=2, ...}) = 0
pipe([9, 10])                           = 0
mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fc9a4897000
mprotect(0x7fc9a4897000, 4096, PROT_NONE) = 0
clone(child_stack=0x7fc9a5096bb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fc9a50979d0, tls=0x7fc9a5097700, child_tidptr=0x7fc9a50979d0) = 3771
ioctl(5, 0x5a39, 0x7fffcfce49f0)        = 0
close(10)                               = 0
futex(0x7fc9a50979d0, FUTEX_WAIT, 3771, NULLM   /data/
+       /data/logrotate.d
+       /data/logrotate.d/openrc
+       /data/logrotate.d/rsyncd
+       /data/logrotate.d/elog-save-summary
+       /data/logrotate.d/._cfg0000_elog-save-summary
+       /data/logrotate.d/syslog-ng
) = 0
close(8

Here is the last few line of an strace of something trying to use /dev/zfs ( strace zfs list ) after that has occured:

brk(0)                                  = 0x16d1000
brk(0x16f2000)                          = 0x16f2000
open("/proc/modules", O_RDONLY)         = 4
fstat(4, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50e23ff000
read(4, "zfs 761063 4 - Live 0xffffffffa0"..., 1024) = 363
close(4)                                = 0
munmap(0x7f50e23ff000, 4096)            = 0
open("/dev/zfs", O_RDWR

Tested on a qemu-kvm vm:
b15 ~ # uname -a
Linux b15 2.6.38-gentoo-r6 #1 SMP Sun Dec 4 20:59:29 EST 2011 x86_64 AMD Phenom(tm) 9550 Quad-Core Processor AuthenticAMD GNU/Linux

Anyhow I'll try and do some more testing and narrow it done some more, if anything comes to mind in the meantime let us know!

[behlendorf]

Interesting, OK well what we need is the kernel stack trace from that close() system call. While the system is in this state you can use sysrq to dump all of the kernel stacks. Just run the following and then find the stack for the zfs diff command. If you can post that in the bug we'll have a better idea why the close is hanging.

# Run as root
> echo t >/proc/sysrq-trigger
> dmesg

[b333z]

No worries, ran this:

b15 ~ # zfs diff data@empty
M       /data/
+       /data/logrotate.d
+       /data/logrotate.d/openrc
+       /data/logrotate.d/rsyncd
+       /data/logrotate.d/elog-save-summary
+       /data/logrotate.d/._cfg0000_elog-save-summary
+       /data/logrotate.d/syslog-ng

Here he is in ps:

root      3791 99.7  0.0  45460  1632 pts/0    R+   13:23   5:53 zfs diff data@empty

The matching stack is:

[  478.440078] zfs             R  running task     4128  3791   3775 0x00000000
[  478.440078]  0000000000000002 0000000000000000 ffff88007d389998 0000000000000010
[  478.440078]  ffff88007807a970 ffff88007806f238 ffff88007d389a68 ffffffffa043ac14
[  478.440078]  ffff88007d3899e8 ffff88007a587800 0000000000000000 0000000000000000
[  478.440078] Call Trace:
[  478.440078]  [<ffffffff81052164>] ? default_spin_lock_flags+0x9/0xd
[  478.440078]  [<ffffffffa044b963>] ? dmu_tx_hold_free+0x783/0x7c9 [zfs]
[  478.440078]  [<ffffffff817839c0>] ? down_read+0x11/0x23
[  478.440078]  [<ffffffffa044beb8>] ? dmu_zfetch+0x50f/0xafc [zfs]
[  478.440078]  [<ffffffffa043962c>] ? dbuf_find+0x31/0xc0 [zfs]
[  478.440078]  [<ffffffff81783716>] ? mutex_lock+0x11/0x38
[  478.440078]  [<ffffffffa044e1f5>] ? dnode_hold_impl+0x12d/0x3a0 [zfs]
[  478.440078]  [<ffffffff81052164>] ? default_spin_lock_flags+0x9/0xd
[  478.440078]  [<ffffffffa043ac14>] ? dbuf_read+0x10d/0x4ea [zfs]
[  478.440078]  [<ffffffffa044e47c>] ? dnode_hold+0x14/0xb6 [zfs]
[  478.440078]  [<ffffffff81052164>] ? default_spin_lock_flags+0x9/0xd
[  478.440078]  [<ffffffffa0441918>] ? dmu_bonus_hold+0x133/0x171 [zfs]
[  478.440078]  [<ffffffff813a6f0f>] ? string+0x4c/0xae
[  478.440078]  [<ffffffffa043ac14>] ? dbuf_read+0x10d/0x4ea [zfs]
[  478.440078]  [<ffffffffa048862f>] ? zap_lockdir+0x4e/0x41f [zfs]
[  478.440078]  [<ffffffffa0489c39>] ? zap_lookup_norm+0x59/0x14f [zfs]
[  478.440078]  [<ffffffffa045b300>] ? dsl_dir_open_spa+0xc9/0x29b [zfs]
[  478.440078]  [<ffffffffa04514b7>] ? dsl_dataset_rele+0x5c/0x8b6 [zfs]
[  478.440078]  [<ffffffffa0009a22>] ? kmem_asprintf+0x4c/0x5a [spl]
[  478.440078]  [<ffffffffa044fb8e>] ? dsl_dataset_fsid_guid+0x28/0xd8 [zfs]
[  478.440078]  [<ffffffffa04533a5>] ? dsl_dataset_get_holds+0x1ee/0x2e5 [zfs]
[  478.440078]  [<ffffffffa045356f>] ? dsl_dataset_user_release+0xd3/0x2c6 [zfs]
[  478.440078]  [<ffffffffa0454553>] ? dsl_dataset_user_release_tmp+0xe8/0x149 [zfs]
[  478.440078]  [<ffffffffa04545a3>] ? dsl_dataset_user_release_tmp+0x138/0x149 [zfs]
[  478.440078]  [<ffffffffa049a1b7>] ? zfs_onexit_destroy+0x5d/0x111 [zfs]
[  478.440078]  [<ffffffffa0492f82>] ? zfsdev_get_state+0xc2/0x3323 [zfs]
[  478.440078]  [<ffffffff8111dd68>] ? fput+0x109/0x1e1
[  478.440078]  [<ffffffff8111b0ea>] ? filp_close+0x63/0x6d
[  478.440078]  [<ffffffff8111b19c>] ? sys_close+0xa8/0xe7
[  478.440078]  [<ffffffff810309d2>] ? system_call_fastpath+0x16/0x1b

After that I checked I could still access the zfs filesystem and cat a file, that was ok.

So thought I would see if I could still browse the snapshot directories:

b15 ~ # cd /data
b15 data # cd .zfs
b15 .zfs # ls
shares  snapshot
b15 .zfs # cd snapshot
b15 snapshot # ls
empty  zfs-diff-3742-00000000ffff994b  zfs-diff-3768-00000000ffffaeff  zfs-diff-3769-00000000ffffa01f  zfs-diff-3791-0000000100003cf8  zfs-diff-3809-000000010000c650
b15 snapshot # cd zfs-diff-3742-00000000ffff994b
    < hangs here >

And that hung so grabbed a stack from bash that was running cd in case it helps:

[ 1320.720739] bash            D ffff88007cb7f978  5408  3797   3794 0x00000000
[ 1320.720739]  ffff880076c1f948 0000000000000086 ffff880076c1f8c8 ffffffff00000001
[ 1320.720739]  ffff880076c1e010 ffff880076c1ffd8 00000000000120c0 ffff88007cb7f600
[ 1320.720739]  ffff88007cb7f980 ffff88007cb7f978 00000000000120c0 00000000000120c0
[ 1320.720739] Call Trace:
[ 1320.720739]  [<ffffffff81783143>] schedule_timeout+0x22/0xbb
[ 1320.720739]  [<ffffffff8106d933>] ? __cond_resched+0x25/0x30
[ 1320.720739]  [<ffffffff81782fc2>] wait_for_common+0xd0/0x150
[ 1320.720739]  [<ffffffff8106bc5e>] ? wake_up_process+0x10/0x12
[ 1320.720739]  [<ffffffff8106bc32>] ? default_wake_function+0x0/0xf
[ 1320.720739]  [<ffffffff817830dc>] wait_for_completion+0x18/0x1a
[ 1320.720739]  [<ffffffff81083d83>] call_usermodehelper_exec+0x76/0xc0
[ 1320.720739]  [<ffffffffa048e783>] zfsctl_snapdir_rename+0x318/0x3c6 [zfs]
[ 1320.720739]  [<ffffffffa048ecf9>] zfsctl_mount_snapshot+0x1b1/0x330 [zfs]
[ 1320.720739]  [<ffffffff81369165>] ? inode_has_perm+0x65/0x67
[ 1320.720739]  [<ffffffff8106cf8d>] ? perf_event_task_sched_out+0x54/0x62
[ 1320.720739]  [<ffffffffa04b2dc3>] zle_decompress+0x5b1/0xac5 [zfs]
[ 1320.720739]  [<ffffffff81125760>] follow_managed+0x119/0x1b8
[ 1320.720739]  [<ffffffff81125a39>] do_lookup+0x1d4/0x287
[ 1320.720739]  [<ffffffff8113416b>] ? mntput_no_expire+0x50/0x141
[ 1320.720739]  [<ffffffff81366b95>] ? security_inode_exec_permission+0x25/0x27
[ 1320.720739]  [<ffffffff8112795c>] link_path_walk+0x232/0x395
[ 1320.720739]  [<ffffffff81127cf2>] do_path_lookup+0x4b/0x109
[ 1320.720739]  [<ffffffff811287c1>] user_path_at+0x51/0x8e
[ 1320.720739]  [<ffffffffa04b2eb3>] ? zle_decompress+0x6a1/0xac5 [zfs]
[ 1320.720739]  [<ffffffff811203d5>] ? cp_new_stat+0xf2/0x108
[ 1320.720739]  [<ffffffff81120485>] vfs_fstatat+0x3c/0x67
[ 1320.720739]  [<ffffffff81120551>] vfs_stat+0x16/0x18
[ 1320.720739]  [<ffffffff8112056d>] sys_newstat+0x1a/0x38
[ 1320.720739]  [<ffffffff810309d2>] system_call_fastpath+0x16/0x1b

[behlendorf]

Thanks for the debug. We'll take a closer look at this once the snapshot code gets a little more formalized.

[b333z]

No worries

[b333z]

Been doing a bit more playing around with this and think I have narrowed the problem down some.

Started with playing with ftrace a bit so I have created some (massive) traces of the issue, that didn't tell me much without a in depth knowledge so thought I would try some good ol' trial and error...

It seems that if I zfs diff between 2 snapshots that are already created, the command works and exits cleanly. eg:

zfs diff data@snap1 data@snap2

The problem only seems to occur when using the single argument form of the zfs diff, eg:

 zfs diff data@snap1

This causes it to create its own snapshot of the data filesystem, which in this case it called: data@zfs-diff-3865-00000000ffffbd25. It is this form of the command that will get stuck.

I can then reboot the vm and run a diff between those 2 snapshots, and the command will exit cleanly:

zfs diff data@snap1 data@zfs-diff-3865-00000000ffffbd25

So looks to be something to do with the onexit handlers/cleanup that happens on close of /dev/zfs if it created a temp snapshot?

Anyhow's it's good the diff is usable with #173 code so might see if I can assist with some testing on that for a bit...

[behlendorf]

This was implemented as part of the .zfs snapshot directory support