[Gluster-users] Fwd: Question about starce output of Glusterfs 3.5

[Jürgen Winkler]

  Hi,

I have 2 questions about a Straceoutput of Glusterfs I hope someone can 
help me to understand.

We have a Webserver who is requesting files from a Gluserfs mount, and 
sometimes it takes a lot of time to get the content so we died a strace 
-f on the glusterfs process on each of the glusterfs servers at the same 
time to see what took him so long to answer.

We found out that


   1. each of the Glusterfs Servers do an open on the file witch is
      requested.
      Why is the open done on both servers an witch one delivers the
      file ??
   2. in the strace there is one call that seem to take very long ( <...
      lstat resumed> {st_mode=S_IFREG|0644, st_size=4314, ...}) = 0
      <0.393390> )but just on one server,what does this mean and what is
      this doing. Can anyone tell me why this take so long ?


The Strace :


auszug vom strace vom gfs am vgfs-01-001:
----------------
11709 18:12:18.824980 
lstat("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
<unfinished ...>
11709 18:12:19.218386 <... lstat resumed> {st_mode=S_IFREG|0644, 
st_size=4314, ...}) = 0 <0.393390>
11709 18:12:19.218431 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.posix.gen", "LR\xdc\xd5\x00\xe1\x06\xea", 8) = 8 <0.000010>
11709 18:12:19.218472 
open("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", O_RDONLY) 
= 45 <0.000031>
11709 18:12:19.218533 read(45, 
"\377\330\377\340\0\20JFIF\0\1\1\0\0\1\0\1\0\0\377\376\0>CREATOR:"..., 
4314) = 4314 <0.037724>
11709 18:12:19.256296 close(45) = 0 <0.000005>
11709 18:12:19.256330 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.afr.distribute1", 0x0, 0) = 12 <0.000008>
11709 18:12:19.256367 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.afr.distribute1", 
"\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00", 12) = 12 <0.000007>
11709 18:12:19.256405 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.afr.distribute2", 0x0, 0) = 12 <0.000029>
11709 18:12:19.256465 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.afr.distribute2", 
"\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00", 12) = 12 <0.000025>
11709 18:12:19.256526 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"glusterfs.inodelk-count", 0x0, 0) = -1 EOPNOTSUPP (Operation not 
supported) <0.000007>
11709 18:12:19.256564 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"glusterfs.entrylk-count", 0x0, 0) = -1 EOPNOTSUPP (Operation not 
supported) <0.000008>
11709 18:12:19.256613 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.glusterfs.dht", 0x0, 0) = -1 ENODATA (No data available) <0.000027>
11709 18:12:19.256669 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.glusterfs.dht.linkto", 0x0, 0) = -1 ENODATA (No data available) 
<0.000024>
11709 18:12:19.256725 
lstat("/gluster-storage/macm01//videos07/15535/preview", 
{st_mode=S_IFDIR|0777, st_size=20480, ...}) = 0 <0.000006>
11709 18:12:19.256766 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview", 
"trusted.posix.gen", "LR\xdc\xd5\x00\xe0\xf3\xb6", 8) = 8 <0.000008>
11709 18:12:19.256815 writev(9, [{":O\0\0\0\22\306\0\0\0\0*", 12}, 
{"\0\0\0\0\0\21\210\315\0\0\0\4\0\0\0\33\0\0\22Z\0\0\0\0\0\0\0\26\0\0\0\0"..., 
4806}], 2) = 4818 <0.000019>
11709 18:12:19.256884 futex(0x613be8, FUTEX_WAIT_PRIVATE, 0, {179, 
743122000} <unfinished ...>
11709 18:12:19.434375 <... futex resumed> ) = 0 <0.177477>
----------------




auszug vom strace vom gfs am vgfs-01-002:
----------------
14254 18:12:18.825614 
lstat("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
<unfinished ...>
14254 18:12:18.901377 <... lstat resumed> {st_mode=S_IFREG|0644, 
st_size=4314, ...}) = 0 <0.075746>
14254 18:12:18.901434 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.posix.gen", "LR\xdc\xdd\x00\xe1\x06\xef", 8) = 8 <0.000010>
14254 18:12:18.901481 
open("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", O_RDONLY) 
= 51 <0.000082>
14254 18:12:18.901594 read(51, <unfinished ...>
14254 18:12:18.914166 <... read resumed> 
"\377\330\377\340\0\20JFIF\0\1\1\0\0\1\0\1\0\0\377\376\0>CREATOR:"..., 
4314) = 4314 <0.012298>
14254 18:12:18.914192 close(51) = 0 <0.000005>
14254 18:12:18.914218 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.afr.distribute1", 0x0, 0) = 12 <0.000009>
14254 18:12:18.914255 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.afr.distribute1", 
"\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00", 12) = 12 <0.000008>
14254 18:12:18.914293 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.afr.distribute2", 0x0, 0) = 12 <0.000078>
14254 18:12:18.914405 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.afr.distribute2", 
"\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00", 12) = 12 <0.000077>
14254 18:12:18.914521 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"glusterfs.inodelk-count", 0x0, 0) = -1 EOPNOTSUPP (Operation not 
supported) <0.000007>
14254 18:12:18.914559 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"glusterfs.entrylk-count", 0x0, 0) = -1 EOPNOTSUPP (Operation not 
supported) <0.000008>
14254 18:12:18.914614 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.glusterfs.dht", 0x0, 0) = -1 ENODATA (No data available) <0.000077>
14254 18:12:18.914725 
lgetxattr("/gluster-storage/macm01//videos07/15535/preview/49be466c51d05.jpg", 
"trusted.glusterfs.dht.linkto", 0x0, 0) = -1 ENODATA (No data available) 
<0.000076>
----------------



THX