[Pvfs2-developers] iozone sanity check fails

Tue Jul 18 13:54:18 EDT 2006

Hi Dean,
I think this might be related to an assertion failure that Julian fixed..
I dont know if it has been committed to tree or not yet?
Thanks,
Murali

On Tue, 18 Jul 2006, Dean Hildebrand wrote:

> Hi All,
>
> I'm noticing that a iozone sanity check fails on the latest cvs code
> with 2.6.16 (fedora core 4).  I think the server is crashing.  I'm doing
> this all on one node.  This works successfully with 1.5.1.
>
> In /var/log/messages:
> Jul 18 13:19:22 foufoune kernel: pvfs2_permission: inode: e4225e10 mask
> = 1 mode = 43ff current->fsuid = 0 inode->i_uid = 0, inode->i_gid = 0
> ret = 0
> Jul 18 13:19:22 foufoune kernel: pvfs2_permission: mode [43ff] & mask
> [1] & S_IRWXO [7] = 1 == mask [1]?
> Jul 18 13:19:22 foufoune kernel: pvfs2_permission: inode: e4225e10 mask
> = 1 mode = 43ff current->fsuid = 0 inode->i_uid = 0, inode->i_gid = 0
> ret = 0
> Jul 18 13:19:22 foufoune kernel: pvfs2_permission: mode [43ff] & mask
> [1] & S_IRWXO [7] = 1 == mask [1]?
> Jul 18 13:19:22 foufoune kernel: pvfs2_lookup called on a2
> Jul 18 13:19:22 foufoune kernel: Alloced OP (e02543a0: 121 OP_LOOKUP)
> Jul 18 13:19:22 foufoune kernel: pvfs2_lookup: doing lookup on a2
> Jul 18 13:19:22 foufoune kernel:   under 1048576,408205455 (follow=no)
> Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation: pvfs2_lookup
> e02543a0
> Jul 18 13:19:22 foufoune kernel: client-core: reading op tag 121 OP_LOOKUP
> Jul 18 13:19:22 foufoune kernel: (get) Alloced OP (e02543a0:121)
> Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation pvfs2_lookup
> returning: -2 for e02543a0.
> Jul 18 13:19:22 foufoune kernel: Lookup Got 0, fsid 0 (ret=-2)
> Jul 18 13:19:22 foufoune kernel: pvfs2_lookup: Adding *negative* dentry
> e4d28914Jul 18 13:19:22 foufoune kernel:   for a2
> Jul 18 13:19:22 foufoune kernel: Releasing OP (e02543a0: 121)
> Jul 18 13:19:22 foufoune kernel: pvfs2_permission: inode: e4225e10 mask
> = 3 mode = 43ff current->fsuid = 0 inode->i_uid = 0, inode->i_gid = 0
> ret = 0
> Jul 18 13:19:22 foufoune kernel: pvfs2_create: called
> Jul 18 13:19:22 foufoune kernel: Alloced OP (e02543a0: 122 OP_CREATE)
> Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation:
> pvfs2_create_file e02543a0
> Jul 18 13:19:22 foufoune kernel: client-core: reading op tag 122 OP_CREATE
> Jul 18 13:19:22 foufoune kernel: (get) Alloced OP (e02543a0:122)
> Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation
> pvfs2_create_file returning: 0 for e02543a0.
> Jul 18 13:19:22 foufoune kernel: Create Got PVFS2 handle 1048573 on fsid
> 408205455 (ret=0)
> Jul 18 13:19:22 foufoune kernel: pvfs2_get_custom_inode: called
> Jul 18 13:19:22 foufoune kernel:   (sb is f6e98600 | MAJOR(dev)=0 |
> MINOR(dev)=0)
> Jul 18 13:19:22 foufoune kernel: pvfs2_alloc_inode: allocated e42251f4
> Jul 18 13:19:22 foufoune kernel: pvfs2_read_inode: e42251f4 (inode =
> 1048573 | ct = 1)
> Jul 18 13:19:22 foufoune kernel: pvfs2_inode_getattr: called on inode
> 1048573
> Jul 18 13:19:22 foufoune kernel: Alloced OP (e0260420: 123 OP_GETATTR)
> Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation:
> pvfs2_inode_getattr e0260420
> Jul 18 13:19:22 foufoune kernel: client-core: reading op tag 123 OP_GETATTR
> Jul 18 13:19:22 foufoune kernel: (get) Alloced OP (e0260420:123)
> Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation
> pvfs2_inode_getattr returning: 0 for e0260420.
> Jul 18 13:19:22 foufoune kernel: attrs->mask = 710007f (1048576, objtype
> = 1), size = 0
> Jul 18 13:19:22 foufoune kernel: pvfs2: copy_attributes_to_inode:
> setting inode->i_mode to 8000 from 0
> Jul 18 13:19:22 foufoune kernel: Getattr on handle 1048573, fsid 408205455
> Jul 18 13:19:22 foufoune kernel:   (inode ct = 1) returned 0
> Jul 18 13:19:22 foufoune kernel: Releasing OP (e0260420: 123)
> Jul 18 13:19:22 foufoune kernel: pvfs2_get_custom_inode: inode e4225224
> allocated
> Jul 18 13:19:22 foufoune kernel:   (pvfs2_inode is e42251f4 | sb is
> f6e98600)
> Jul 18 13:19:22 foufoune kernel: Assigned file inode new number of 1048573
> Jul 18 13:19:22 foufoune kernel: pvfs2_create_file: Instantiating
> Jul 18 13:19:22 foufoune kernel:  *negative* dentry e4d28914 for a2
> Jul 18 13:19:22 foufoune kernel: Releasing OP (e02543a0: 122)
> Jul 18 13:19:22 foufoune kernel: pvfs2_create: returning 0
> Jul 18 13:19:22 foufoune kernel: pvfs2_permission: inode: e4225224 mask
> = 0 mode = 8000 current->fsuid = 0 inode->i_uid = 0, inode->i_gid = 0
> ret = 0
> Jul 18 13:19:22 foufoune kernel: pvfs2_permission: mode [8000] & mask
> [0] & S_IRWXO [7] = 0 == mask [0]?
> Jul 18 13:19:22 foufoune kernel: pvfs2_file_open: called on a2 (inode is
> 1048573)
> Jul 18 13:19:22 foufoune kernel: pvfs2_file_open returning normally: 0
> Jul 18 13:19:22 foufoune kernel: pvfs2_setattr: called on a2
> Jul 18 13:19:22 foufoune kernel: pvfs2: pvfs2_truncate called on inode
> 1048573 with size 0
> Jul 18 13:19:22 foufoune kernel: pvfs2: pvfs2_truncate_inode 1048573:
> Handle is 1048573 | fs_id 408205455 | size is 0
> Jul 18 13:19:22 foufoune kernel: Alloced OP (e02543a0: 124 OP_TRUNCATE)
> Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation:
> pvfs2_truncate_inode e02543a0
> Jul 18 13:19:22 foufoune kernel: client-core: reading op tag 124 OP_TRUNCATE
> Jul 18 13:19:32 foufoune kernel: (get) Alloced OP (e02543a0:124)
> Jul 18 13:19:32 foufoune kernel: pvfs2: service_operation
> pvfs2_truncate_inode returning: -111 for e02543a0.
> Jul 18 13:19:32 foufoune kernel: pvfs2: pvfs2_truncate got return value
> of -111
> Jul 18 13:19:32 foufoune kernel: Releasing OP (e02543a0: 124)
> Jul 18 13:19:32 foufoune kernel: pvfs2_setattr: inode_setattr returned 0
> Jul 18 13:19:32 foufoune kernel: Alloced OP (e02543a0: 125 OP_SETATTR)
> Jul 18 13:19:32 foufoune kernel: mode is 32768 | translated perms is 0
> Jul 18 13:19:32 foufoune kernel: pvfs2: service_operation:
> pvfs2_inode_setattr e02543a0
> Jul 18 13:19:32 foufoune kernel: client-core: reading op tag 125 OP_SETATTR
> Jul 18 13:19:42 foufoune kernel: (get) Alloced OP (e02543a0:125)
> Jul 18 13:19:42 foufoune kernel: pvfs2: service_operation
> pvfs2_inode_setattr returning: -111 for e02543a0.
> Jul 18 13:19:42 foufoune kernel: pvfs2_inode_setattr: returning -111
> Jul 18 13:19:42 foufoune kernel: Releasing OP (e02543a0: 125)
> Jul 18 13:19:42 foufoune kernel: pvfs2_setattr: returning -111
> Jul 18 13:19:42 foufoune kernel: pvfs2_file_release: called on a2
>
> I attached the /tmp/pvfs2-client.log:
>
> I didn't have logging on the server, but there isn't any errors in the
> server log.
>
> The code that fails (from iozone.c) is below.  I just ran 'iozone -aec
> -i 0 -i 1 -+n -f /mnt/pvfs2/a2'
> /* Sanity check */
> /* Some filesystems do not behave correctly and fail
>  * when this sequence is performned. This is a very
>  * bad thing. It breaks many applications and lurks
>  * around quietly. This code should never get
>  * triggered, but in the case of running iozone on
>  * an NFS client, the filesystem type on the server
>  * that is being exported can cause this failure.
>  * If this failure happens, then the NFS client is
>  * going to going to have problems, but the acutal
>  * problem is the filesystem on the NFS server.
>  * It's not NFS, it's the local filesystem on the
>  * NFS server that is not correctly permitting
>  * the sequence to function.
>  */
>         if((fd = I_OPEN(filename, (int)O_CREAT|O_WRONLY,0))<0)
>         {
>                 printf("\nCan not open temp file: %s\n",
>                         filename);
>                 perror("open");
>                 exit(44);
>         }
>         wval=ftruncate(fd,0);
>         if(wval < 0)
>         {
>                 printf("Sanity check failed. Do not deploy this
> filesystem in a production environment !\n");
>                 exit(44);
>         }
>         close(fd);
>         unlink(filename);
> /* Sanity check */
>
> --
> Dean Hildebrand
> Ph.D. Candidate
> University of Michigan
>
>