[ENBD] 2.4.32

Thu Feb 5 09:40:14 MST 2004

"Also sprach Tad Kollar:"
> > Could you put right at the front of the routine something like the test
> > for alignment that occurs later on just before the write?
> 
> Done, log attached...

OK - confirms 512B requests, and also at 512B offsets:

   Feb  5 10:37:17 gmass4 enbd-server: enbd-server 10878: <#1190>
   do_srv_write
   request for nonblock offset 0x7e00 (32256) seqno 1 len 512 
   Feb  5 10:37:17 gmass4 enbd-server: enbd-server 10878: <#1194>
   do_srv_write
   request for nonblock length 0x7e00 (32256) seqno 1 len 512 

That may have been a fluke, since it was #1 in sequence, and maybe it
was the read of the partition table. But there are many more:

   Feb  5 10:37:17 gmass4 enbd-server: enbd-server 10878: <#1194>
   do_srv_write
   request for nonblock length 0x14600 (83456) seqno 101 len 512 

Incidentally, this printout is still not right:

   Feb  5 10:37:17 gmass4 enbd-server: enbd-server 10878: <#1334>
   do_srv_write
   write to nonblock offset 0x8400 (33792) seqno 4 len 0 

That "len 0" has to go! It was len 512 in this case.

A check of the log for the strange offsets shows:

  oboe:/usr/oboe/ptb% zgrep "request for nonblock offset" syslog7.gz | \
  sed -e 's/.* len //'| sort -n | uniq -c
     4093 512 
     2019 4096 
     50 8192 
     1 14336 
     1 30208 
     85 32768 

which seems indeed to show lots of the very short requests, but also
some misalgned requests of size 4096 and above.

Looking for strange lengths shows something else:

  oboe:/usr/oboe/ptb% zgrep "request for nonblock len" syslog7.gz | \
  sed -e 's/.* len //' | sort -n | uniq -c
     4679 512 
     1 1536 
  oboe:/usr/oboe/ptb% 

Which seems to show that all the odd length requests are themselves
short, except one! I wonder where that one was to ...

   Feb  5 10:43:19 gmass4 enbd-server: enbd-server 10897: <#1194>
   do_srv_write
   request for nonblock length 0x131983ec00 (82032454656) seqno 175777 len 1536 
   Feb  5 10:43:19 gmass4 enbd-server: enbd-server 10897: <#1326>
   do_srv_write
   req seqno 175777 from 0x131983ec00 len 1536 with 0 emitted, got 1536 from net making 1536 tot/1536 rem 
   Feb  5 10:43:19 gmass4 enbd-server: file 10897: <#1097> fileit
   write of nonblock length at 131983ec00 (82032454656), len 1536! 

Amazingly, the read from the network socket was of 1536 bytes on a
nonblocking socket, MTU 1500. There's  now very good information coming
from that print statement.

I am curious as to where all these short requests are directed ... but
the offsets are all different:

oboe:/usr/oboe/ptb% zgrep "request for nonblock len" syslog7.gz | sed -e 's/.* length .*(\(.*\)).*/\1/' | sort -n | uniq -c
      2 32256
      1 32768
      1 33280
      1 83456
      1 83968
      1 84480
      1 30735324160
      1 30735324672
      1 30735325184
      1 61470618624
      1 61470619136
      1 61470619648
      1 71715700736
      1 81960796160
      1 81960796672
      1 81960830464
      1 81960830976
      1 81960831488
      1 81960881664
      1 81960882176
      1 81960882688
      1 81960932864
      1 81960933376
      ...

Actually, I do see some pattern. Several are consective writes. 

oboe:/usr/oboe/ptb% zgrep "request for nonblock len" syslog7.gz | sed -e 's/.* length \([^ ]*\) .*/\1/' | sort -n | uniq -c

      1 0x10b296c000
      1 0x13153e8000
      1 0x13153e8200
      1 0x13153f0600
      1 0x13153f0800
      1 0x13153f0a00
      1 0x13153fce00
      1 0x13153fd000
      1 0x13153fd200
      1 0x1315409600
      1 0x1315409800
      1 0x1315409a00
      1 0x1315415e00
      1 0x1315416000
      1 0x1315416200
      1 0x1315422600
      1 0x1315422800
      1 0x1315422a00
     ...

Becomes clearer maybe if I transform these to sector counts...

oboe:/usr/oboe/ptb% zgrep "request for nonblock len" syslog7.gz | sed -e 's/.* length .*(\(.*\)).*/\1/' | awk '{ print $1/512 }' | uniq -c 

      1 63
      1 64
      1 65
      1 163
      1 164
      1 165
      1 320159321
      1 320159322
      1 320159323
      1 160079747
      1 160079748
      1 160079749
      1 160079847
      1 160079848
      1 160079849
      1 160079947
      1 160079948
      1 160079949
      1 160080047
      1 160080048
      1 160080049
      1 160080147
      1 160080148
      1 160080149
      1 160080247
      1 160080248
      1 160080249
      ...

Yes. Weird or what! Those are writes of areas of three contiguous
sectors, one sector at at time. And if I look at the sequence one
can clearly see that those groups of 3 are separated by 100 sectors
distance. It goes on like that. The end is quite interesting:

      ...
      1 160235994
      1 160235995
      1 160235996
      1 60029930
      1 60029931
      1 60029932
      1 120059802
      1 120059803
      1 120059804
      1 200099598
      1 200099599
      1 200099600
      1 260129470
      1 280139391
      1 280139392
      1 63
      1 160219638
      1 160079681
      1 240119488
      1 140069728
      1 160079680

To me, it looks like it wrote one huge file lying at about 160079747
writing "oddly" every hundred sectors. Before and after it did some
FS management near the 32015932 and  240119488 sector marks, as
well as doing something down in the 63 sector range.

Anyway .. what to conclude? Yes, you have sector-aligned writes. What
should one do? They even come in groups of three! One can't guarantee
to write those atomically through a file system. Hmmm.

Peter