Le Thu, 10 Feb 2011 14:01:05 +0900 (JST), Ryusuke Konishi <ryusuke@xxxxxxxx> a écrit : > O.K. so, it seems like something happened at the checkpoint 15731 > according to your information. > > One thing wired is that the timestamp (mtime) looks to be rewinded > at cp15731. > > > File: « mnt/snap6/cut/f5_20110125_202053.ts(0).Xcl » > > Size: 6214528000 Blocks: 18446744073697366064 IO Block: > > 4096 fichier Device: fe00h/65024d Inode: 14 > > Links: 0 Access: (0644/-rw-r--r--) Uid: ( 1000/philippe) Gid: > > ( 100/ users) Access: 2011-01-24 01:30:02.260271565 +0100 > > Modify: 2011-01-24 01:30:02.260271565 +0100 > > Change: 2011-01-25 20:28:48.894851740 +0100 > > Do you have any ideas on this timestamp ? Hi, I pastebin all the lscp (25600 lines) at : http://dpaste.org/U6w6 As you can see, there is an activity at 2011-01-24 01:30:02. 14442 2011-01-24 01:29:56 cp - 101 11 14443 2011-01-24 01:30:00 cp - 925 11 14444 2011-01-24 01:30:07 cp - 625 11 14445 2011-01-25 20:20:58 cp - 320 12 14446 2011-01-25 20:21:05 cp - 544 12 philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14443 /dev/mapper/vg11a-video mnt/snap4 philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14444 /dev/mapper/vg11a-video mnt/snap5 philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14445 /dev/mapper/vg11a-video mnt/snap6 philippe@micro11:~$ ls -lid mnt/snap4/**/** 12 drwxr-xr-x 2 philippe users 4096 23 janv. 22:34 mnt/snap4/capture/ 19 -rw-r--r-- 1 philippe users 4957184000 24 janv. 01:29 mnt/snap4/capture/f2_20110123_223415.ts 16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 mnt/snap4/capture/f3_20110107_205154.ts 14 -rw-r--r-- 1 philippe users 6213324800 24 janv. 01:30 mnt/snap4/capture/f3_20110123_223247.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap4/capture/f4_20110119_204007.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 mnt/snap4/capture/tf1hd_20101219_203305_schrek2.ts 18 -rw-r--r-- 1 philippe users 4434 9 janv. 15:45 mnt/snap4/channels.conf 13 drwxr-xr-x 2 philippe users 4096 23 janv. 22:31 mnt/snap4/cut/ philippe@micro11:~$ ls -lid mnt/snap5/**/** 12 drwxr-xr-x 2 philippe users 4096 23 janv. 22:34 mnt/snap5/capture/ 19 -rw-r--r-- 1 philippe users 4958387200 24 janv. 01:30 mnt/snap5/capture/f2_20110123_223415.ts 16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 mnt/snap5/capture/f3_20110107_205154.ts 14 -rw-r--r-- 1 philippe users 6214528000 24 janv. 01:30 mnt/snap5/capture/f3_20110123_223247.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap5/capture/f4_20110119_204007.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 mnt/snap5/capture/tf1hd_20101219_203305_schrek2.ts 18 -rw-r--r-- 1 philippe users 4434 9 janv. 15:45 mnt/snap5/channels.conf 13 drwxr-xr-x 2 philippe users 4096 23 janv. 22:31 mnt/snap5/cut/ philippe@micro11:~$ ls -lid mnt/snap6/**/** 12 drwxr-xr-x 2 philippe users 4096 25 janv. 20:20 mnt/snap6/capture/ 19 -rw-r--r-- 1 philippe users 4958387200 24 janv. 01:30 mnt/snap6/capture/f2_20110123_223415.ts 16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 mnt/snap6/capture/f3_20110107_205154.ts 14 -rw-r--r-- 1 philippe users 6214528000 24 janv. 01:30 mnt/snap6/capture/f3_20110123_223247.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap6/capture/f4_20110119_204007.ts 20 -rw-r--r-- 1 philippe users 1203200 25 janv. 20:20 mnt/snap6/capture/f5_20110125_202053.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 mnt/snap6/capture/tf1hd_20101219_203305_schrek2.ts 18 -rw-r--r-- 1 philippe users 4434 9 janv. 15:45 mnt/snap6/channels.conf 13 drwxr-xr-x 2 philippe users 4096 23 janv. 22:31 mnt/snap6/cut/ Interesting file is : 14 -rw-r--r-- 1 philippe users 6214528000 24 janv. 01:30 mnt/snap5/capture/f3_20110123_223247.ts It's the timestamp, the size (6214528000) and the inode (14) of the file of the cp15731. For your information, at 1:30 the computer shuts down with 'at' command. Another remark : 2 files were recorded simultaneously (the other one is f2_20110123_223415.ts at inode 19). This file is delete in cp 14522. I don't see any trouble after deletion : philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14521 /dev/mapper/vg11a-video mnt/snap1 philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14522 /dev/mapper/vg11a-video mnt/snap2 philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14523 /dev/mapper/vg11a-video mnt/snap3 philippe@micro11:~$ ls -lid mnt/snap1/**/** 12 drwxr-xr-x 2 philippe users 4096 25 janv. 20:26 mnt/snap1/capture/ 16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 mnt/snap1/capture/f3_20110107_205154.ts 14 -rw-r--r-- 1 philippe users 6214528000 24 janv. 01:30 mnt/snap1/capture/f3_20110123_223247.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap1/capture/f4_20110119_204007.ts 20 -rw-r--r-- 1 philippe users 192512000 25 janv. 20:28 mnt/snap1/capture/f5_20110125_202053.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 mnt/snap1/capture/tf1hd_20101219_203305_schrek2.ts 18 -rw-r--r-- 1 philippe users 4434 9 janv. 15:45 mnt/snap1/channels.conf 13 drwxr-xr-x 2 philippe users 4096 25 janv. 20:27 mnt/snap1/cut/ 21 -rw-r--r-- 1 philippe 1000 48 25 janv. 20:23 mnt/snap1/cut/f2_20110123_223415.ts(0).Xcl 19 -rw-r--r-- 1 philippe 1000 47 25 janv. 20:27 mnt/snap1/cut/f3_20110123_223247.ts philippe@micro11:~$ ls -lid mnt/snap2/**/** 12 drwxr-xr-x 2 philippe users 4096 25 janv. 20:28 mnt/snap2/capture/ 16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 mnt/snap2/capture/f3_20110107_205154.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap2/capture/f4_20110119_204007.ts 20 -rw-r--r-- 1 philippe users 196121600 25 janv. 20:28 mnt/snap2/capture/f5_20110125_202053.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 mnt/snap2/capture/tf1hd_20101219_203305_schrek2.ts 18 -rw-r--r-- 1 philippe users 4434 9 janv. 15:45 mnt/snap2/channels.conf 13 drwxr-xr-x 2 philippe users 4096 25 janv. 20:27 mnt/snap2/cut/ 21 -rw-r--r-- 1 philippe 1000 48 25 janv. 20:23 mnt/snap2/cut/f2_20110123_223415.ts(0).Xcl 19 -rw-r--r-- 1 philippe 1000 47 25 janv. 20:27 mnt/snap2/cut/f3_20110123_223247.ts philippe@micro11:~$ ls -lid mnt/snap3/**/** 12 drwxr-xr-x 2 philippe users 4096 25 janv. 20:28 mnt/snap3/capture/ 16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 mnt/snap3/capture/f3_20110107_205154.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap3/capture/f4_20110119_204007.ts 20 -rw-r--r-- 1 philippe users 199731200 25 janv. 20:29 mnt/snap3/capture/f5_20110125_202053.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 mnt/snap3/capture/tf1hd_20101219_203305_schrek2.ts 18 -rw-r--r-- 1 philippe users 4434 9 janv. 15:45 mnt/snap3/channels.conf 13 drwxr-xr-x 2 philippe users 4096 25 janv. 20:27 mnt/snap3/cut/ 21 -rw-r--r-- 1 philippe 1000 48 25 janv. 20:23 mnt/snap3/cut/f2_20110123_223415.ts(0).Xcl 19 -rw-r--r-- 1 philippe 1000 47 25 janv. 20:27 mnt/snap3/cut/f3_20110123_223247.ts Remark : cp 14522 is at 2011-01-25 20:29:09 like the Change timestamp: 2011-01-25 20:28:48.894851740 +0100 that appears in the cp15731. > > Then, let's look back in a different perspective. > > As you know, the lscp command displays the total number of inodes > (ICNT). Does it match the actual number of files and directories ? Last line : 5631 2011-02-07 20:27:54 cp - 21 10 And philippe@micro11:~$ find /mnt/tmp1 /mnt/tmp1 /mnt/tmp1/.nilfs /mnt/tmp1/capture /mnt/tmp1/capture/f3_20110107_205154.ts /mnt/tmp1/capture/tf1hd_20101219_203305_schrek2.ts /mnt/tmp1/capture/f2_20110130_174456.ts /mnt/tmp1/capture/f4_20110119_204007.ts /mnt/tmp1/capture/f3_20110206_144851.ts /mnt/tmp1/channels.conf /mnt/tmp1/cut /mnt/tmp1/cut/f3_20110206_145141.ts(0).Xcl gives 10 files for me. That seems OK. Recently I noticed this message in dmesg : Feb 8 21:34:29 localhost kernel: nilfs_palloc_commit_free_entry: entry number 14 already freed and Feb 6 20:53:30 localhost kernel: nilfs_palloc_commit_free_entry: entry number 19 already freed (remember inode 19 was the second file's one) and the system hangs on umount the nilfs (slow task I presume) : Feb 7 22:21:50 localhost nilfs_cleanerd[1819]: shutdown Feb 7 22:21:50 localhost kernel: nilfs_palloc_commit_free_entry: entry number 14 already freed Feb 7 22:22:10 localhost kernel: nilfs_palloc_commit_free_entry: entry number 14 already freed Feb 7 22:25:12 localhost -- MARK -- Feb 7 22:27:02 localhost kernel: umount.nilfs2 D ffff88003f861bc0 0 2499 2498 0x00000000 Feb 7 22:27:02 localhost kernel: ffff88002c2cbc28 0000000000000086 ffff88002c2cbfd8 ffff88002c2cbfd8 Feb 7 22:27:02 localhost kernel: ffff88002c2cbfd8 ffff88003f861bc0 ffff88002c2cbfd8 ffff88002c2cbfd8 Feb 7 22:27:02 localhost kernel: ffff88002c2cbfd8 ffff88003f861ea0 ffff88002c2cbfd8 ffff88002c2ca000 Feb 7 22:27:02 localhost kernel: Call Trace: Feb 7 22:27:02 localhost kernel: [<ffffffff810480bc>] ? finish_task_switch+0x3c/0xd0 Feb 7 22:27:02 localhost kernel: [<ffffffff813a3ca1>] ? schedule+0x381/0xaa0 Feb 7 22:27:02 localhost kernel: [<ffffffff810e62f0>] ? find_get_pages_tag+0x100/0x130 Feb 7 22:27:02 localhost kernel: [<ffffffff813a49bd>] schedule_timeout+0x2bd/0x340 Feb 7 22:27:02 localhost kernel: [<ffffffff810eea44>] ? write_cache_pages+0x114/0x4e0 Feb 7 22:27:02 localhost kernel: [<ffffffff8104ee9b>] ? check_preempt_wakeup+0x18b/0x240 Feb 7 22:27:02 localhost kernel: [<ffffffff810ee3f0>] ? __writepage+0x0/0x40 Feb 7 22:27:02 localhost kernel: [<ffffffff813a37d0>] wait_for_common+0xc0/0x160 Feb 7 22:27:02 localhost kernel: [<ffffffff8104fe00>] ? default_wake_function+0x0/0x10 Feb 7 22:27:02 localhost kernel: [<ffffffff813a3918>] wait_for_completion+0x18/0x20 Feb 7 22:27:02 localhost kernel: [<ffffffff81159333>] sync_inodes_sb+0x83/0x180 Feb 7 22:27:02 localhost kernel: [<ffffffff8115de00>] __sync_filesystem+0x80/0x90 Feb 7 22:27:02 localhost kernel: [<ffffffff8115de73>] sync_filesystem+0x43/0x60 Feb 7 22:27:02 localhost kernel: [<ffffffff811373df>] generic_shutdown_super+0x2f/0x100 Feb 7 22:27:02 localhost kernel: [<ffffffff811374dc>] kill_block_super+0x2c/0x50 Feb 7 22:27:02 localhost kernel: [<ffffffff81137825>] deactivate_locked_super+0x45/0x60 Feb 7 22:27:02 localhost kernel: [<ffffffff811386b5>] deactivate_super+0x45/0x60 Feb 7 22:27:02 localhost kernel: [<ffffffff81151436>] mntput_no_expire+0x86/0xf0 Feb 7 22:27:02 localhost kernel: [<ffffffff81151f37>] sys_umount+0x67/0x370 Feb 7 22:27:02 localhost kernel: [<ffffffff8100bf12>] system_call_fastpath+0x16/0x1b Feb 7 22:29:02 localhost kernel: umount.nilfs2 D ffff88003f861bc0 0 2499 2498 0x00000000 Now I don't use this filesystem. I just keep it for debug and umount if OK. Regards, PhC -- To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
