<div dir="ltr">Straces are interesting, but don&#39;t immediately open my eyes:<div><br></div><div>strace of grep on NFS (works as expected)</div><div><br></div><div><div>openat(AT_FDCWD, &quot;/home/griznog/pipetest.tmp.txt&quot;, O_RDONLY) = 3</div><div>fstat(3, {st_mode=S_IFREG|0644, st_size=530721, ...}) = 0</div><div>ioctl(3, TCGETS, 0x7ffe2c26b0b0)        = -1 ENOTTY (Inappropriate ioctl for device)</div><div>read(3, &quot;chr1\t43452652\t43452652\tL1HS\tlib1&quot;..., 32768) = 32768</div><div>lseek(3, 32768, SEEK_HOLE)              = 530721</div><div>lseek(3, 32768, SEEK_SET)               = 32768</div><div>fstat(1, {st_mode=S_IFREG|0644, st_size=5977, ...}) = 0</div><div>mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3bf6c43000</div><div>write(1, &quot;chr1\t43452652\t43452652\tL1HS\tlib1&quot;..., 8192chr1 </div></div><div><br></div><div>strace on GPFS (thinks file is binary)</div><div><div><br></div><div>openat(AT_FDCWD, &quot;/srv/gsfs0/projects/pipetest.tmp.txt&quot;, O_RDONLY) = 3</div><div>fstat(3, {st_mode=S_IFREG|0644, st_size=530721, ...}) = 0</div><div>ioctl(3, TCGETS, 0x7ffc9b52caa0)        = -1 ENOTTY (Inappropriate ioctl for device)</div><div>read(3, &quot;chr1\t43452652\t43452652\tL1HS\tlib1&quot;..., 32768) = 32768</div><div>lseek(3, 32768, SEEK_HOLE)              = 262144</div><div>lseek(3, 32768, SEEK_SET)               = 32768</div><div>fstat(1, {st_mode=S_IFREG|0644, st_size=6011, ...}) = 0</div><div>mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd45ee88000</div><div>close(3)                                = 0</div><div>write(1, &quot;Binary file /srv/gsfs0/projects/&quot;..., 72Binary file /srv/gsfs0/projects/levinson/xwzhu/pipetest.tmp.txt matches</div><div>) = 72</div></div><div><br></div><div>Do the lseek() results indicate that the grep on the GPFS mounted version thinks the file is a sparse file? For comparison I strace&#39;d md5sum in place of the grep and it does not lseek() with SEEK_HOLE, it&#39;s access in both cases look identical, like:</div><div><br></div><div><div>open(&quot;/home/griznog/pipetest.tmp.txt&quot;, O_RDONLY) = 3</div><div>fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0</div><div>fstat(3, {st_mode=S_IFREG|0644, st_size=530721, ...}) = 0</div><div>mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb7d2c2b000</div><div>read(3, &quot;chr1\t43452652\t43452652\tL1HS\tlib1&quot;..., 32768) = 32768</div><div>...[reads clipped]...</div><div>read(3, &quot;&quot;, 24576)                      = 0<br></div><div>lseek(3, 0, SEEK_CUR)                   = 530721</div><div>close(3)                                = 0</div></div><div><br></div><div><br></div><div>jbh</div><div><br></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Feb 14, 2018 at 9:51 AM, Aaron Knister <span dir="ltr">&lt;<a href="mailto:aaron.s.knister@nasa.gov" target="_blank">aaron.s.knister@nasa.gov</a>&gt;</span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Just speculating here (also known as making things up) but I wonder if<br>
grep is somehow using the file&#39;s size in its determination of binary<br>
status. I also see mmap in the strace so maybe there&#39;s some issue with<br>
mmap where some internal GPFS buffer is getting truncated<br>
inappropriately but leaving a bunch of null values which gets returned<br>
to grep.<br>
<br>
-Aaron<br>
<span class=""><br>
On 2/14/18 10:21 AM, John Hanks wrote:<br>
&gt; Hi Valdis,<br>
&gt;<br>
&gt; I tired with the grep replaced with &#39;ls -ls&#39; and &#39;md5sum&#39;, I don&#39;t think<br>
&gt; this is a data integrity issue, thankfully:<br>
&gt;<br>
&gt; $ ./pipetestls.sh <br>
&gt; 256 -rw-r--r-- 1 39073 3001 530721 Feb 14 07:16<br>
&gt; /srv/gsfs0/projects/pipetest.<wbr>tmp.txt<br>
&gt; 0 -rw-r--r-- 1 39073 3953 530721 Feb 14 07:16 /home/griznog/pipetest.tmp.txt<br>
&gt;<br>
&gt; $ ./pipetestmd5.sh <br>
&gt; 15cb81a85c9e450bdac8230309453a<wbr>0a  /srv/gsfs0/projects/pipetest.<wbr>tmp.txt<br>
&gt; 15cb81a85c9e450bdac8230309453a<wbr>0a  /home/griznog/pipetest.tmp.txt<br>
&gt;<br>
&gt; And replacing grep with &#39;file&#39; even properly sees the files as ASCII:<br>
&gt; $ ./pipetestfile.sh <br>
&gt; /srv/gsfs0/projects/pipetest.<wbr>tmp.txt: ASCII text, with very long lines<br>
&gt; /home/griznog/pipetest.tmp.<wbr>txt: ASCII text, with very long lines<br>
&gt;<br>
&gt; I&#39;ll poke a little harder at grep next and see what the difference in<br>
&gt; strace of each reveals.<br>
&gt;<br>
&gt; Thanks,<br>
&gt;<br>
&gt; jbh<br>
&gt;<br>
&gt;<br>
&gt;<br>
&gt;<br>
&gt; On Wed, Feb 14, 2018 at 7:08 AM, &lt;<a href="mailto:valdis.kletnieks@vt.edu">valdis.kletnieks@vt.edu</a><br>
</span><div><div class="h5">&gt; &lt;mailto:<a href="mailto:valdis.kletnieks@vt.edu">valdis.kletnieks@vt.<wbr>edu</a>&gt;&gt; wrote:<br>
&gt;<br>
&gt;     On Wed, 14 Feb 2018 06:20:32 -0800, John Hanks said:<br>
&gt;<br>
&gt;     &gt; #  ls -aln /srv/gsfs0/projects/pipetest.<wbr>tmp.txt $HOME/pipetest.tmp.txt<br>
&gt;     &gt; -rw-r--r-- 1 39073 3953 530721 Feb 14 06:10 /home/griznog/pipetest.tmp.txt<br>
&gt;     &gt; -rw-r--r-- 1 39073 3001 530721 Feb 14 06:10<br>
&gt;     &gt; /srv/gsfs0/projects/pipetest.<wbr>tmp.txt<br>
&gt;     &gt;<br>
&gt;     &gt; We can &quot;fix&quot; the user case that exposed this by not using a temp file or<br>
&gt;     &gt; inserting a sleep, but I&#39;d still like to know why GPFS is behaving this way<br>
&gt;     &gt; and make it stop.<br>
&gt;<br>
&gt;     May be related to replication, or other behind-the-scenes behavior.<br>
&gt;<br>
&gt;     Consider this example - 4.2.3.6, data and metadata replication both<br>
&gt;     set to 2, 2 sites 95 cable miles apart, each is 3 Dell servers with<br>
&gt;     a full<br>
&gt;     fiberchannel mesh to 3 Dell MD34something arrays.<br>
&gt;<br>
&gt;     % dd if=/dev/zero bs=1k count=4096 of=sync.test; ls -ls sync.test;<br>
&gt;     sleep 5; ls -ls sync.test; sleep 5; ls -ls sync.test<br>
&gt;     4096+0 records in<br>
&gt;     4096+0 records out<br>
&gt;     4194304 bytes (4.2 MB) copied, 0.0342852 s, 122 MB/s<br>
&gt;     2048 -rw-r--r-- 1 root root 4194304 Feb 14 09:35 sync.test<br>
&gt;     8192 -rw-r--r-- 1 root root 4194304 Feb 14 09:35 sync.test<br>
&gt;     8192 -rw-r--r-- 1 root root 4194304 Feb 14 09:35 sync.test<br>
&gt;<br>
&gt;     Notice that the first /bin/ls shouldn&#39;t be starting until after the<br>
&gt;     dd has<br>
&gt;     completed - at which point it&#39;s only allocated half the blocks<br>
&gt;     needed to hold<br>
&gt;     the 4M of data at one site.  5 seconds later, it&#39;s allocated the<br>
&gt;     blocks at both<br>
&gt;     sites and thus shows the full 8M needed for 2 copies.<br>
&gt;<br>
&gt;     I&#39;ve also seen (but haven&#39;t replicated it as I write this) a small<br>
&gt;     file (4-8K<br>
&gt;     or so) showing first one full-sized block, then a second full-sized<br>
&gt;     block, and<br>
&gt;     then dropping back to what&#39;s needed for 2 1/32nd fragments.  That had me<br>
&gt;     scratching my head<br>
&gt;<br>
&gt;     Having said that, that&#39;s all metadata fun and games, while your case<br>
&gt;     appears to have some problems with data integrity (which is a whole lot<br>
&gt;     scarier).  It would be *really* nice if we understood the problem here.<br>
&gt;<br>
&gt;     The scariest part is:<br>
&gt;<br>
&gt;     &gt; The first grep | wc -l returns 1, because grep outputs  &quot;Binary file /path/to/<br>
&gt;     &gt; gpfs/mount/test matches&quot;<br>
&gt;<br>
&gt;     which seems to be implying that we&#39;re failing on semantic consistency.<br>
&gt;     Basically, your &#39;cat&#39; command is completing and closing the file,<br>
&gt;     but then a<br>
&gt;     temporally later open of the same find is reading something other<br>
&gt;     that only the<br>
&gt;     just-written data.  My first guess is that it&#39;s a race condition<br>
&gt;     similar to the<br>
&gt;     following: The cat command is causing a write on one NSD server, and<br>
&gt;     the first<br>
&gt;     grep results in a read from a *different* NSD server, returning the<br>
&gt;     data that<br>
&gt;     *used* to be in the block because the read actually happens before<br>
&gt;     the first<br>
&gt;     NSD server actually completes the write.<br>
&gt;<br>
&gt;     It may be interesting to replace the grep&#39;s with pairs of &#39;ls -ls /<br>
&gt;     dd&#39; commands to grab the<br>
&gt;     raw data and its size, and check the following:<br>
&gt;<br>
&gt;     1) does the size (both blocks allocated and logical length) reported by<br>
&gt;     ls match the amount of data actually read by the dd?<br>
&gt;<br>
&gt;     2) Is the file length as actually read equal to the written length,<br>
&gt;     or does it<br>
&gt;     overshoot and read all the way to the next block boundary?<br>
&gt;<br>
&gt;     3) If the length is correct, what&#39;s wrong with the data that&#39;s<br>
&gt;     telling grep that<br>
&gt;     it&#39;s a binary file?  ( od -cx is your friend here).<br>
&gt;<br>
&gt;     4) If it overshoots, is the remainder all-zeros (good) or does it<br>
&gt;     return semi-random<br>
&gt;     &quot;what used to be there&quot; data (bad, due to data exposure issues)?<br>
&gt;<br>
&gt;     (It&#39;s certainly not the most perplexing data consistency issue I&#39;ve<br>
&gt;     hit in 4 decades - the<br>
&gt;     winner *has* to be a intermittent data read corruption on a GPFS 3.5<br>
&gt;     cluster that<br>
&gt;     had us, IBM, SGI, DDN, and at least one vendor of networking gear<br>
&gt;     all chasing our<br>
&gt;     tails for 18 months before we finally tracked it down. :)<br>
&gt;<br>
&gt;     ______________________________<wbr>_________________<br>
&gt;     gpfsug-discuss mailing list<br>
</div></div>&gt;     gpfsug-discuss at <a href="http://spectrumscale.org" rel="noreferrer" target="_blank">spectrumscale.org</a> &lt;<a href="http://spectrumscale.org" rel="noreferrer" target="_blank">http://spectrumscale.org</a>&gt;<br>
&gt;     <a href="http://gpfsug.org/mailman/listinfo/gpfsug-discuss" rel="noreferrer" target="_blank">http://gpfsug.org/mailman/<wbr>listinfo/gpfsug-discuss</a><br>
&gt;     &lt;<a href="http://gpfsug.org/mailman/listinfo/gpfsug-discuss" rel="noreferrer" target="_blank">http://gpfsug.org/mailman/<wbr>listinfo/gpfsug-discuss</a>&gt;<br>
<span class="im HOEnZb">&gt;<br>
&gt;<br>
&gt;<br>
&gt;<br>
&gt; ______________________________<wbr>_________________<br>
&gt; gpfsug-discuss mailing list<br>
&gt; gpfsug-discuss at <a href="http://spectrumscale.org" rel="noreferrer" target="_blank">spectrumscale.org</a><br>
&gt; <a href="http://gpfsug.org/mailman/listinfo/gpfsug-discuss" rel="noreferrer" target="_blank">http://gpfsug.org/mailman/<wbr>listinfo/gpfsug-discuss</a><br>
&gt;<br>
<br>
</span><span class="HOEnZb"><font color="#888888">--<br>
Aaron Knister<br>
NASA Center for Climate Simulation (Code 606.2)<br>
Goddard Space Flight Center<br>
<a href="tel:%28301%29%20286-2776" value="+13012862776">(301) 286-2776</a><br>
</font></span><div class="HOEnZb"><div class="h5">______________________________<wbr>_________________<br>
gpfsug-discuss mailing list<br>
gpfsug-discuss at <a href="http://spectrumscale.org" rel="noreferrer" target="_blank">spectrumscale.org</a><br>
<a href="http://gpfsug.org/mailman/listinfo/gpfsug-discuss" rel="noreferrer" target="_blank">http://gpfsug.org/mailman/<wbr>listinfo/gpfsug-discuss</a><br>
</div></div></blockquote></div><br></div>