Fsys.eide problem with SanDisk flash drive

QNX Newsgroups (Archives) qdn.public.qnx4
1

We’ve encountered a problem with certain SanDisk flash drives (we use
SD25B-128 drives on an ATA bus) under QNX 4.25, and if any of you can shed
light on it, I’d appreciate it greatly.

We have code which uses a fairly simple sequence of fopen(),
fprintf()…fprintf(), fclose() calls to write to a file of approximately
2200 bytes. With certain of the SanDisk units*, the first 1024 bytes are
written, but not the rest of the data, even though the file size is updated
to indicate the correct length. Thus, when the data is read back later,
random, pre-existing data from the drive is returned at the end of the file.
Using a logic analyzer on the ATA bus, we have confirmed that no data beyond
the first 1024 bytes is provided to the drive.

  • The units which fail in this manner appear to be working, but very slowly.
    The “completed successfully” IRQ after the write of the first 1024 bytes
    comes after about 24.5 msecs, whereas with other units not exhibiting this
    problem, the IRQ comes after only about 2.5 msecs. Curiously, the drives
    report themselves as “removeable”…

The system calls do not report any errors. Changing the system calls to
open(), write(), close() makes no difference. Likewise, using setbuf() to
disable buffering does not help. However, if Fsys is started with the ‘-d0’
option, and mount is given the ‘-s’ option, the drive units appear to
function correctly.

While the drives are abnormally slow, they can hardly be considered “faulty”
if they succeed at writing the data they are given, and are never given the
remaining data. The source code itself is beyond question. This appears to
be the fault of the QNX device driver at some low level. Does anyone know of
bugs or issues with the drivers which cause this sort of bad behavior?

2

Kent Radek <karadek@essvote.com> wrote:

We’ve encountered a problem with certain SanDisk flash drives (we use
SD25B-128 drives on an ATA bus) under QNX 4.25, and if any of you can shed
light on it, I’d appreciate it greatly.

We have code which uses a fairly simple sequence of fopen(),
fprintf()…fprintf(), fclose() calls to write to a file of approximately
2200 bytes. With certain of the SanDisk units*, the first 1024 bytes are
written, but not the rest of the data, even though the file size is updated
to indicate the correct length. Thus, when the data is read back later,
random, pre-existing data from the drive is returned at the end of the file.
Using a logic analyzer on the ATA bus, we have confirmed that no data beyond
the first 1024 bytes is provided to the drive.

  • The units which fail in this manner appear to be working, but very slowly.
    The “completed successfully” IRQ after the write of the first 1024 bytes
    comes after about 24.5 msecs, whereas with other units not exhibiting this
    problem, the IRQ comes after only about 2.5 msecs. Curiously, the drives
    report themselves as “removeable”…

The system calls do not report any errors. Changing the system calls to
open(), write(), close() makes no difference. Likewise, using setbuf() to
disable buffering does not help. However, if Fsys is started with the ‘-d0’
option, and mount is given the ‘-s’ option, the drive units appear to
function correctly.

While the drives are abnormally slow, they can hardly be considered “faulty”
if they succeed at writing the data they are given, and are never given the
remaining data. The source code itself is beyond question. This appears to
be the fault of the QNX device driver at some low level. Does anyone know of
bugs or issues with the drivers which cause this sort of bad behavior?

I don’t know of any known bugs, but I’m not a subject matter expert there.

The extremely long delay to the write complete irq might be being seen
as a hardware fault.

Can you try increasing the trace level to 6, and then checking to
see if Fsys has generated any tracelogs after this happens?

Can you also try doing your test with an
open( … O_DSYNC ) and then checking the result of the write() call
and seeing if it gives a success or failure back?

-David

QNX Training Services
http://www.qnx.com/support/training/
Please followup in this newsgroup if you have further questions.

3

“David Gibbs” <dagibbs@qnx.com> wrote in message
news:ausec7$co2$1@nntp.qnx.com…

I don’t know of any known bugs, but I’m not a subject matter expert there.

The extremely long delay to the write complete irq might be being seen
as a hardware fault.

That’s pretty much what I was guessing…I’m just not sure how to check
whether that’s the case.

Can you try increasing the trace level to 6, and then checking to
see if Fsys has generated any tracelogs after this happens?

I’ve attached a tracelog, but I’m still pretty new to QNX and didn’t know
anything about tracelogs before your message. So if my ignorance shines
through, feel free to enlighten me. I passed “-v 6” to Fsys – hope that was
the trace level you were talking about. For reference when perusing the log,
the file was written at 11:45:38.

Can you also try doing your test with an
open( … O_DSYNC ) and then checking the result of the write() call
and seeing if it gives a success or failure back?

Setting O_DSYNC causes the file to be written successfully…so, of course,
no errors are returned.

Thanks,
Kent


begin 666 Trace.zip
M4$L#!!0(`/59(BX,:ZHRN@0``$4L```%5%)!0T7=6E%OVS80?B_0
M_W![2X"A)271D@KXP<E2;-T0#$O1/1:JK=1"$ZF39!?;KQ\I)39C’2\ZB0.*
M’5!4<#Y^/GYW$K\3_“XK000@Y9M(O0D”"$#HB%1\VUWHD-V%U/Z3U*UZC^1
M%S!O’SQ;B2#"1X^CCGXA,VO+]QX<3L.)E.0<“8”=0[75^^ACYLV:W?-,@2X
MS8J[? -?ZVH-’?KCYN\S=9;N&^NRBUT@F\K[.RN2]:N%[]“E4)^V(#41 N
MHV@U-<RX"^72?K\DB($(3>D CM#?U>W9EMW%8U[,HO9?6MX_P1FKQLH<S6
M7T[YPMF=Y&8PP<-CG>3&XYU$YH.TR $O9-RWR!-%WYXT1M8^-@:<7?UR_6’U
MV[F;,91=C:T9SRK]\UY5^1O60/_Y’5%+!7]TN1A:?’<TNBX[V1:)953N=4C
MPVAOZ?#1N4PV”“AX]9_’@OD/D@O;“8K8”;P00/CRG@QN,D/D@“L2S%7 S
MF.#A,07<>%P!,A]$@<1Y’XU5X,#@[8ER9&0_4:REW”=^GPOK-2#$E?)6S54
MPLU@@H>/5QP\W@MD/L->T(JI[J]BA1NUDUA#M(FA[-=6;1+8W^:!E 7M?+ M6&S[/R[5%K)FO0Q$]_]?2[$]K:?F/71(TG=(]'R'Z$_Z'KGYX_)G-^748A$, M)GAXI%@$'BT6G0]2+#E;3>#“1X>4”-QQ4@\T$4L$RTZ]‘UC +C;‘7HWU9_
M’]^</U5-"C6T239^4!5)X>6C#1M919%&N!#JNII^!2$ ?F,3)9;\CI2\H
M!C&/8=I09&W9RU036E[XI$2!.!;AHKNXN-29#3;D9C#!PZ=(D=UX%% YH/P
MJT-!I(0/1G1]TFC]K_7EOJ;04OZZ6_XJL4MRL%=X;;.8R5D#@,D'I.0.0S0 M^2#\!^OLR\99C%P;9R]EVKC0/0*,K21SJ"'Q6"690PV=#\)OC0GY^)8!0X,
MWGKAR,CN!6LIMQ>LT<27\4S^(X_L]NICB:</DA>L’!XVW+G#XBMP$>J0#!
M8('1Q0@*@”=#Z(A)Z1Q-J)P*7IA4[$_!ZD^]?;S<"BG*?W16;K.V/LK:X MSZM=.V29JR-S,"#QF([,P8#.!]'1/1B,56"</;=@ONSY=_#-TTQMY-G41NX7 MVV.+R'Q53^+3X11 X/$V9KZJCV;;>H+!! ^/*<"T]70^E *^?(C%R/4A]E*F M#XEF3Q<$@PD>'JLD<[J@\T$J:7G8B8_DV,OAF,RNA)O!! ^?#M^?$'B\$F0^ M2"52+SH>S)VW._/(R+XSK:7<.]/:AZ]S=+:3)QA,\/!8BS&=/)W/L,74;"=/ M,)C@X1$%"#RJ)T/HH 7)Z\LWSOMH:G<OS.9SV"“AT^O.‘B$LQ?SJ@1KC8.
MG:YVS’+”%"O/IEB%7OIJMK4F&$SP%A7,TUG0_2%<<?GE!3E@7S=3JHV::>
M8##!PV/:,TT]G0\BJO+2P^I8&C&Q&+D&A![=. _!WX>M6L6:,B<>?EYE!
M>7;KJ:#5?3WX:KX]MP\J&7^DU)GCSZPNB+S#[ (0ZCV>5WOR@:VV3Z’
M:KW>U76^>04WU7T.;9VM<\CW^N!LXYJVE<O7_P+4$L!A0% ````@]5DB M+@QKJC*Z! ``12P```4``````````0@+:!`````%1204-%4$L%!@`````! -``$,P```-T$````````
`
end

4

Kent Radek <karadek@essvote.com> wrote:

“David Gibbs” <> dagibbs@qnx.com> > wrote in message
news:ausec7$co2$> 1@nntp.qnx.com> …

I don’t know of any known bugs, but I’m not a subject matter expert there.

The extremely long delay to the write complete irq might be being seen
as a hardware fault.

That’s pretty much what I was guessing…I’m just not sure how to check
whether that’s the case.

Can you try increasing the trace level to 6, and then checking to
see if Fsys has generated any tracelogs after this happens?

I’ve attached a tracelog, but I’m still pretty new to QNX and didn’t know
anything about tracelogs before your message. So if my ignorance shines
through, feel free to enlighten me. I passed “-v 6” to Fsys – hope that was
the trace level you were talking about. For reference when perusing the log,
the file was written at 11:45:38.

No – I was talking about the Proc tracelevel, to control what goes into
the tracelog.

tracectrl will set the level
tracelogger will extract the trace information in a compact but not
human readable form
traceinfo will extract the info in a human readable form, or translate the
output generated by tracelogger

tracectrl -s 6

will set the tracelevel to 6. Basically… Proc throws away everything
less important than the level set – doesn’t matter what Fsys generates.

Can you also try doing your test with an
open( … O_DSYNC ) and then checking the result of the write() call
and seeing if it gives a success or failure back?

Setting O_DSYNC causes the file to be written successfully…so, of course,
no errors are returned.

Hm…very odd.

-David

QNX Training Services
http://www.qnx.com/support/training/
Please followup in this newsgroup if you have further questions.

5

“David Gibbs” <dagibbs@qnx.com> wrote in message
news:av24sd$rep$1@nntp.qnx.com…

Kent Radek <> karadek@essvote.com> > wrote:

I’ve attached a tracelog, but I’m still pretty new to QNX and didn’t
know
anything about tracelogs before your message. So if my ignorance shines
through, feel free to enlighten me. I passed “-v 6” to Fsys – hope that
was
the trace level you were talking about. For reference when perusing the
log,
the file was written at 11:45:38.

No – I was talking about the Proc tracelevel, to control what goes into
the tracelog.

Slowly, realization dawns… Okay, I’ve attached a new trace with all events
of severity 6 or higher. There doesn’t appear to be anything new in regards
to the /dev/hd0 device, though. The file was written at 16:43:38.

Setting O_DSYNC causes the file to be written successfully…so, of
course,
no errors are returned.

Hm…very odd.

My theory as to why the drive is taking so long to respond is that it’s
accumulating “things” (keep in mind that this is a flash drive) in its
internal cache until it reaches a point where there’s no more cache and it
must actually complete a previous task to respond to the current write. If
all (or most) writes are synchronous, and thus slower (more widely spaced),
the backlog never builds to the point where extremely long delays are seen.
I know, it sounds kind of…odd…but I don’t know much about the internal
workings of flash drives.


begin 666 Trace.zip
M4$L#!!0(`$F (BX,D$Z\B 4``( P```%5%)!0T7=6EUOVS84?2_0
M_W#WE@!;3(GZ+."’).NP=44P+$7W6- 2G0BQ4^BG;:_?E>28SLVR9&1U’T0
M""PXE^<>WD/QDKQ^QP00’[SH34#?^!%$0+ %A,1 X P_SN’F[0<X_GY'-Z7 M=T7&%E,O@#DK%CR'LTWVB4G)LGO(9+6 U8,\?_WJG0;4IRTH#3O0KNU 0_@! M;LJ<@R@E% (_<KYDJPL]GIED. :wink::&"2T1@DXX%)QF.03 8FF8Q!,AV89.I& MTM^"H@(>@OKTD.1/'=*J*C/XM(=;UG=P]O:7FX^7[PV(U&MI!NF69K6ISV%3 MY/#(:OC*J]+0E71=DVW7PKXK[Z*$S=L^)-<!OOXV)Y0HWUR8A\8[5,W?-2O
MU>'99+F53[K7:<'RF2\R=%_J_2QD#;KI20"Z1(X=Y6<$DYYO)?4[PE=FP
M19$SB:.9?0%9+‘FYEJ<H6P)A/’\NB(]_3]]<M0]7US0ZE4B/T#0W^U0Q9?3V
MB3,^/IS8)UM[CW@>?,2 IPG($F[P8)N&G417)6+12%.YE.RDW!NXV; F9ST
MUDZ/T#0W>Y5V>GNU=D8^RJ!&6^U`K<K]BA@A;IY(85JC0$>/<QQYC"V602
M3F:%F-3W)^^P%BDP(E5++1+FM[ 5FN[R487Y".?5E)"<M %">.P%A7/RCM1
M?$798(*Y8]<-G,%EFY>+80=I;=CU"T]SL5;+K[=6R&_DH9$]U8L6NLFN1 M$B-2MM(BA2S@^U#N'A1C"#M[CZ1PF]4%U%S4Z&,M"CDE4.-74Q]X54UC<M_] M<QK>ZNSJ4:SS^G1#4BJ^5H;S;4<H0)3!/+U%$51+(9PX’9@&/XISU[^)+
MAXJ)>EE(N+G%4K1[@/,$KC)C.))JC^"_J’H?W_8-F’]9NHY]MBW[#Y(<#
M:788:$@RL<6]/MF7DH0N&#9SH:(.+Y9>V9A?+3’M%SO=EQP2>XV:)2JC@A(
M5)2P+“L.;”%Y)7#O!'E5;‘A5ZR&-IPZ$M#]U’/+4IXY9-^B"8)CZK!ST(P)
MK>(.^<F-P=A,A_'P2Y$+![;P6SD$79V!J,[H#\1QU.Y&S9"0’7K<^TME(
M+]J3S_+QW$0=1J@%.$X#K+.4OH2 ZV.U9’ <O=G"20UV/-WHD_%&F8UM
MYD4W:#(TE&C^I+S$_5TL0A=HZI%BERCZNT’;;H4Q>V+U:7H9YY>^*Y;$]L M2?H#D_3'($D')DG'(!D,3-*E>&1-TK)X9$W2I7AD3=*R>&1-TJ5X=$ARG$2A M6XABUPL1/9+KA8@>R7P=4(A"1B$Y@?/[WGH9$)KF9G_YHXN]\M;+S$=QZ>"/ M/8MH[Q#K$9KF9J\*L=Y>'6(C'T6(Z=@A#GJ'6(_0-#=[58CU]NH0&_DH0AR, M'^+.6TNPH[J8O.CNAB3D"WFA]CA+VOG,+],$U73I[]C=,>T5SG=DE,4>_I
MJ$=HFIO]U:6+O7HZ&ODHIF/O^J<!H6EN]JH(.-8_S7R4$5#GZ=1\R)1LIDK3
M6C3S07-9?%[BCNP$KG>)TX#0-#=[E3R.)4XS’X4\3^5$R[H2VH]25]KQZ+.L
M’M3Y7KBLIG;+JF^_K*9VRZK+&30@0_PT(["K107#UZ+^!9Y?6 6SZ6^J@@4#
M5$“J\LL3KK=3H0^'7<[@==W@30@-,W-_CIVL5<ND&8^BEG8^V!H0&B:F[TJ
MHX'0S,?900L)AEY*C:XWY@&=)#UK/?QTH#0-#=[E5".QTLS'X505L?+UA4A MJ>?[SD)9':[Z.>B9P0\IFC(XM<[@!XC&#.YR0?L-TF\I,N=P6&B4?*%;_I
M?H=Z^_OUS\CY#U:)0MQ]!T$<0XFQJ=:BAGNVX5!FV;JJ>'X!M^62@ZQ8QH%O
M,$_5@%LS>?'ZU5]02P$”% 4````" !)@"(N#)!.O(@%``" , ``!0`````` G```!" MH$`````5%)!0T502P4&``````$``0S````JP4`````
`
end