BeebSCSI 7_7

for bbc micro/electron hardware, peripherals & programming issues (NOT emulators!)
User avatar
Elminster
Posts: 3979
Joined: Wed Jun 20, 2012 8:09 am
Location: Essex, UK
Contact:

Re: BeebSCSI 7_7

Post by Elminster » Thu Aug 15, 2019 10:37 pm

Manually shorted the detect pin to ground, while typing mount, required 3 hands, and it works then. So reflow it is.

And the debug was indeed reporting no card.

Code: Select all

FAT FS: mmc_disk_initialize(): Executing
FAT FS: power_off(): Powering down SD card
FAT FS: mmc_disk_initialize(): ERROR: No card detected in socket
File system: filesystemMount(): ERROR: FR_NOT_READY - No SD Card reports not ready!


SCSI State: Resetting SCSI emulation
SCSI State: Firmware: V002.004
Emulation mode is Winchester (ADFS SCSI-1 hard-drive)

SCSI State: Bus Free
SCSI State: Information transfer phase: Data out

User avatar
simoni
Posts: 498
Joined: Wed May 25, 2016 6:18 pm
Contact:

Re: BeebSCSI 7_7

Post by simoni » Fri Aug 16, 2019 4:01 am

Great. Also you should upgrade the firmware; 2.5 is the current version (and contains some nice performance improvements for big files).

User avatar
Elminster
Posts: 3979
Joined: Wed Jun 20, 2012 8:09 am
Location: Essex, UK
Contact:

Re: BeebSCSI 7_7

Post by Elminster » Fri Aug 16, 2019 6:40 am

It was after 2.5 firmware upgrade issue happened, so I downgraded it to see if that fixed issue. Obviously just s coincidence.

User avatar
Elminster
Posts: 3979
Joined: Wed Jun 20, 2012 8:09 am
Location: Essex, UK
Contact:

Re: BeebSCSI 7_7

Post by Elminster » Fri Aug 16, 2019 10:38 am

Original BeebSCSI now fixed and working again.

Of the two new BeebSCSIs I built, one works and the other one has the same not registering card issue. I did check that before I hooked it up but now pin 15 not going to ground also. So it appears if the connection is not great then the mechanical stress of plugging and unplugging the sdcard breaks it.

Just need to get the thrid beebscsi fixed and then run the stress test on all 3. Might try a physical stress test as well, plug and unplug sdcard a few hundred times!

User avatar
hoglet
Posts: 8776
Joined: Sat Oct 13, 2012 6:21 pm
Location: Bristol
Contact:

Re: BeebSCSI 7_7

Post by hoglet » Fri Aug 16, 2019 10:57 am

Elminster wrote:
Fri Aug 16, 2019 10:38 am
Of the two new BeebSCSIs I built, one works and the other one has the same not registering card issue. I did check that before I hooked it up but now pin 15 not going to ground also. So it appears if the connection is not great then the mechanical stress of plugging and unplugging the sdcard breaks it.
It is slighly awkward to re-solder the SD Card switch connections.

Here's a photo that shows the back of the SD Card socket:
IMG_1732.JPG
There are two connections: the left one is the ground connection, and the middle one connects though a large via to pin 15 of the microcontroller.

In my case, it was the connection in the middle that was dodgy. I reflowed it with a fine tipped soldering iron bit, in conjunction with a small amount of flux, and it's been fine ever since.

I should also say, it was hard to tell with a visual inspection that there was anything wrong.

Dave

User avatar
simoni
Posts: 498
Joined: Wed May 25, 2016 6:18 pm
Contact:

Re: BeebSCSI 7_7

Post by simoni » Fri Aug 16, 2019 11:12 am

If they are soldered correctly, you would need a silly amount of force to break the solder; try pulling a SMT cap off a board without heating it and you'll find out just how strong solder is. Basically, if you don't heat both the PCB pad and the pin of the component you will end up flowing solder only on one - with the pressure from the other pads you will then get an intermittent connection due to one half resting on the other - which will work/not work as the metal casing flexes from card insertions.

There are really only two sure-fire (simple) ways to solder hard to reach pins/pads with a high degree of accuracy: hot-air reflow or a fine tip iron under a soldering microscope.

Stress-testing a socket after soldering to see if your soldering was good is only going to result in faster wear on the socket. Get a cheap microscope from ebay (one of the cheap hand-help USB toys) - it's enough for a good post-assembly visual inspection (and is especially useful whilst learning to solder SMT devices).

User avatar
danielj
Posts: 7694
Joined: Thu Oct 02, 2008 4:51 pm
Location: Manchester
Contact:

Re: BeebSCSI 7_7

Post by danielj » Fri Aug 16, 2019 11:21 am

Elminster wrote:
Fri Aug 16, 2019 10:38 am
Original BeebSCSI now fixed and working again.

Of the two new BeebSCSIs I built, one works and the other one has the same not registering card issue. I did check that before I hooked it up but now pin 15 not going to ground also. So it appears if the connection is not great then the mechanical stress of plugging and unplugging the sdcard breaks it.

Just need to get the thrid beebscsi fixed and then run the stress test on all 3. Might try a physical stress test as well, plug and unplug sdcard a few hundred times!
If you checked just by installing the firmware, it won't tell you if that pin was well connected. The firmware will install regardless of the insert-detect.

d.

User avatar
Elminster
Posts: 3979
Joined: Wed Jun 20, 2012 8:09 am
Location: Essex, UK
Contact:

Re: BeebSCSI 7_7

Post by Elminster » Fri Aug 16, 2019 11:28 am

danielj wrote:
Fri Aug 16, 2019 11:21 am
Elminster wrote:
Fri Aug 16, 2019 10:38 am
Original BeebSCSI now fixed and working again.

Of a the two new BeebSCSIs I built, one works and the other one has the same not registering card issue. I did check that before I hooked it up but now pin 15 not going to ground also. So it appears if the connection is not great then the mechanical stress of plugging and unplugging the sdcard breaks it.
If you checked just by installing the firmware, it won't tell you if that pin was well connected. The firmware will install regardless of the insert-detect.

d.
Yep. I discovered that from the other board. This was tested with a multimeter.
Last edited by Elminster on Fri Aug 16, 2019 11:38 am, edited 1 time in total.

User avatar
Elminster
Posts: 3979
Joined: Wed Jun 20, 2012 8:09 am
Location: Essex, UK
Contact:

Re: BeebSCSI 7_7

Post by Elminster » Fri Aug 16, 2019 11:33 am

simoni wrote:
Fri Aug 16, 2019 11:12 am
If they are soldered correctly, you would need a silly amount of force to break the solder; try pulling a SMT cap off a board without heating it and you'll find out just how strong solder is. Basically, if you don't heat both the PCB pad and the pin of the component you will end up flowing solder only on one - with the pressure from the other pads you will then get an intermittent connection due to one half resting on the other - which will work/not work as the metal casing flexes from card insertions.

There are really only two sure-fire (simple) ways to solder hard to reach pins/pads with a high degree of accuracy: hot-air reflow or a fine tip iron under a soldering microscope.
I do have all the gear, but at the time I didn’t realise it would be a pain, or I would have got the solder paste out of the fridge. Although saying that those connectors were soldered on all 3 boards in Sept last year, just I didn't finish boards 2 & 3 till this year. Was only the second surface board I had done at the time, done a dozen or so since, so wouldn't have had the experience to know that it would be an issue. I don’t plan to make more anyway, but other people might find info useful. [Edited]

I have ripped off usb connectors, but only by accident.
Last edited by Elminster on Fri Aug 16, 2019 11:57 am, edited 4 times in total.

User avatar
Elminster
Posts: 3979
Joined: Wed Jun 20, 2012 8:09 am
Location: Essex, UK
Contact:

Re: BeebSCSI 7_7

Post by Elminster » Fri Aug 16, 2019 11:40 am

hoglet wrote:
Fri Aug 16, 2019 10:57 am
Elminster wrote:
Fri Aug 16, 2019 10:38 am
Of the two new BeebSCSIs I built, one works and the other one has the same not registering card issue. I did check that before I hooked it up but now pin 15 not going to ground also. So it appears if the connection is not great then the mechanical stress of plugging and unplugging the sdcard breaks it.
It is slighly awkward to re-solder the SD Card switch connections.

Here's a photo that shows the back of the SD Card socket:
IMG_1732.JPG

Dave

You board looks different? It that one of the mini ones?
Last edited by Elminster on Fri Aug 16, 2019 11:56 am, edited 1 time in total.

User avatar
simoni
Posts: 498
Joined: Wed May 25, 2016 6:18 pm
Contact:

Re: BeebSCSI 7_7

Post by simoni » Fri Aug 16, 2019 11:55 am

Hoglet's board is a 7_5 PCB - the 7_7s have a more compact Molex microSD socket that's easier to solder (7_7 is the current PCB release version).

User avatar
Elminster
Posts: 3979
Joined: Wed Jun 20, 2012 8:09 am
Location: Essex, UK
Contact:

Re: BeebSCSI 7_7

Post by Elminster » Fri Aug 16, 2019 7:12 pm

Lucky I don't have the hard to solder sdcard slots then.

All 3 working now.

Soak tested the first one for 2 hrs using the basic program (only a couple of minutes doing the writing). Some turning off and on again, and reinserting card a few times (dont worry I am not doing it hundreds). Played with transfer and the beebscsi rom, all work fine. I would say that is a pass.

Onto next 2 cards now. All looking good thanks.

User avatar
BeebMaster
Posts: 2962
Joined: Sun Aug 02, 2009 4:59 pm
Location: Lost in the BeebVault!
Contact:

Re: BeebSCSI 7_7

Post by BeebMaster » Sat Jan 11, 2020 9:39 pm

Thanks to IanS and Prime at the November ABug I now have the serial doings added to my BeebSCSI board and finally today I have done a bit of testing.

(As an aside I found every serial port logger command I tried in Linux to be extremely unreliable. I've tried putty, screen, ttylog and others and they all spuriously dropped tons of data. In the end I fell back to good old cat which works much better, although still looks to have lost some of the log lines. Using

Code: Select all

sudo cat /dev/ttyUSB0 | ts %c | tee BeebSCSIlog11-1-2020
I get timestamped output to screen and a log file.)

The disc error 2C problems I was getting quite regularly previously may have been primarily due to my rather Heath-Robinson lash-up for powering BeebSCSI, but now I've got a nice solid power connector on it, and it's not really recurred since, barring one episode this afternoon when experimenting with the different logging utils, so it's not conclusive how that happened. If I get a spurious 2C again I will try to replicate it "scientifically" and log it.

The issue I'm still having is that some disc accesses are much slower than I would expect, and much slower than a CF-based IDE hard drive. Using BeebSCSI in a Level 3 file server is a good test, so here's what I logged on a Master Turbo:

Ctrl-A-BREAK
Shift-BREAK
L3 file server then loads and mounts 4 512MB discs.
This takes about 8 minutes with logging on, without logging it takes about 4 minutes which is comparable to SCSI2SD and the CF hard drive.
User station logs on, DIRs to a directory with over 100 files and EXes the directory.
The EX is very slow and sluggish on screen.
User station logs off.
File server is stopped with Q followed by *BYE.

I've attached the whole log with a bit of annotation showing these stages. I think *EX is a good example for BeebSCSI because it is very disc-read intensive for the file server. Whereas in ADFS it involves only loading 5 contiguous sectors into workspace, for the file server it is somewhat different. This is because the file server structure does not store the length of any file. Instead the file length must be calculated. So the file server loads the directory into the cache (the 13 sector read in the log) and then works through the directory entries by loading the map sector of each object - the successive reads of a single sector shown in the log. The map sector identifies where on the disc all the fragments of the file are located, and how many sectors long each fragment is. It also stores the LSB only of the file length. So file length = total number of sectors * 256 + LSB.

With logging this operation takes 58 seconds. It's 50 seconds with the logging off. The CF based drive does this operation in 8 seconds.

So it's clear that there is some significant disc-access overhead in BeebSCSI that isn't present in other systems. I can't tell, and I'm no expert in FAT, but I think the message

Code: Select all

File system: filesystemOpenLunForRead(): Successful
at the beginning of every data read is a clue - I interpret that as meaning that the .dat file held on the SD card's file structure is repeatedly being opened and closed every time ADFS requests a sector. I would have thought that a start unit command should open the .dat file and leave it open until a stop unit command?
Attachments
BeebSCSIlog11-1-2020Annotated.zip
(121.13 KiB) Downloaded 4 times
Image

User avatar
simoni
Posts: 498
Joined: Wed May 25, 2016 6:18 pm
Contact:

Re: BeebSCSI 7_7

Post by simoni » Sun Jan 12, 2020 5:09 am

If the application (in this case a file server) is repeatedly opening and closing LUNs; then there is going to be some overhead as BeebSCSI opens and closes the files in the exFAT partition of the SDcard.

Unlike CF card solutions and SCSI2SD, BeebSCSI implements supports full exFAT file system on the SD card - the other solutions just write raw sectors to the media. In pretty much all common use-cases exFAT is a massive advantage - you can pop the SD card into your PC, copy LUNs on and off, open them with ADFS explorer and mount them with BeebEm... try doing that with a DC or SCSI2SD CF/SD card...

exFAT support also enables the jukebox functionality in BeebSCSI; allowing you to have hundreds of accessible LUN images (very useful for setting up various dev/music/etc environments in different jukes).

If you really, really, really, really need a 2Gbyte Acorn file server... then perhaps you should use something with less cross-LUN overhead. For everything else, BeebSCSI with exFAT support is superior.

If you want to have a go at speeding up the inter-LUN switching; well, the source code is on github, you are welcome to give it a bash. BeebSCSI (unlike every other solution) was designed to be open source and open hardware from the very beginning - so there is a wealth of documentation and clearly commented code to help you along.

User avatar
BeebMaster
Posts: 2962
Joined: Sun Aug 02, 2009 4:59 pm
Location: Lost in the BeebVault!
Contact:

Re: BeebSCSI 7_7

Post by BeebMaster » Tue Jan 14, 2020 12:48 am

I've fixed it. It was nothing to do with any of that, it was just a simple compile error in the code.

I tried lots of things, the first of which was to reformat my card from FAT32 to ex-FAT, which gave an immediate improvement, to about 35 seconds EXing the directory on the file server, without debug logging turned on.

I then started looking at the code and tried various things, none of which helped. I put a lot more debug output lines in filesystem.c to see exactly what was going wrong.

The problem is very basic, and nothing to do with file servers or multiple LUNs being in use, simply this: seeking a high sector number inside a LUN takes a long time.

This is the debug output of version 2.5 doing a mount and then a load of a BASIC file which then does a single OSWORD &72 read of 16 sectors at &1F0000, ie. very near the end of a 512MB image:
BeebSCSI 2.5 wrote:Tue,14 Jan 2020.00:05:34.278087
Tue,14 Jan 2020.00:05:34.278229 BeebSCSI - Acorn SCSI-1 Emulation
Tue,14 Jan 2020.00:05:34.278367
Tue,14 Jan 2020.00:05:34.278488 (c)2018-2019 Simon Inns
Tue,14 Jan 2020.00:05:34.278608 https://www.domesday86.com
Tue,14 Jan 2020.00:05:34.278727 Open-source GPLv3 firmware
Tue,14 Jan 2020.00:05:34.278845
Tue,14 Jan 2020.00:05:34.278960 Firmware: V002.005
Tue,14 Jan 2020.00:05:34.279074 Emulation mode is Winchester (ADFS SCSI-1 hard-drive)
Tue,14 Jan 2020.00:05:34.279190 USB capable board not detected
Tue,14 Jan 2020.00:05:34.279304
Tue,14 Jan 2020.00:05:43.343388 File system: filesystemReset(): Resetting file system
Tue,14 Jan 2020.00:05:43.427593 File system: filesystemReset(): File system is flagged as mounted
Tue,14 Jan 2020.00:05:43.427757 File system: filesystemCheckLunImage(): Flushing the file system
Tue,14 Jan 2020.00:05:43.427839 File system: filesystemCheckLunImage(): Checking for (.dat) LUN image 0
Tue,14 Jan 2020.00:05:43.427916 File system: filesystemCheckLunImage(): LUN image found
Tue,14 Jan 2020.00:05:43.427991 File system: filesystemCheckLunImage(): LUN size in bytes (according to .dat) = 553648128
Tue,14 Jan 2020.00:05:43.428065 File system: filesystemCheckLunImage(): WARNING: The LUN file size is greater than 512Mbs
Tue,14 Jan 2020.00:05:43.511880 File system: filesystemCheckLunImage(): Checking for (.dsc) LUN descriptor 0
Tue,14 Jan 2020.00:05:43.511996 File system: filesystemCheckLunImage(): LUN descriptor found
Tue,14 Jan 2020.00:05:43.512036 File system: filesystemGetLunSizeFromDsc(): Flushing the file system
Tue,14 Jan 2020.00:05:43.512073 File system: LUN Descriptor contents:
Tue,14 Jan 2020.00:05:43.512110 File system: Mode Select Parameter List:
Tue,14 Jan 2020.00:05:43.512146 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:05:43.512183 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:05:43.512219 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:05:43.512255 File system: Length of Extent Descriptor List (8) = 8
Tue,14 Jan 2020.00:05:43.512291 File system: Extent Descriptor List:
Tue,14 Jan 2020.00:05:43.512327 File system: Density code = 0
Tue,14 Jan 2020.00:05:43.596211 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:05:43.596328 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:05:43.596368 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:05:43.596405 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:05:43.596441 File system: Block size = 256
Tue,14 Jan 2020.00:05:43.596477 File system: Drive Parameter List:
Tue,14 Jan 2020.00:05:43.596514 File system: List format code = 1
Tue,14 Jan 2020.00:05:43.596550 File system: Cylinder count = 1024
Tue,14 Jan 2020.00:05:43.596585 File system: Data head count = 64
Tue,14 Jan 2020.00:05:43.596621 File system: Reduced write current cylinder = 128
Tue,14 Jan 2020.00:05:43.596657 File system: Write pre-compensation cylinder = 128
Tue,14 Jan 2020.00:05:43.596693 File system: Landing zone position = 0
Tue,14 Jan 2020.00:05:43.596729 File system: Step pulse output rate code = 1
Tue,14 Jan 2020.00:05:43.680541 File system: filesystemCheckLunImage(): LUN size in bytes (according to .dsc) = 553648128
Tue,14 Jan 2020.00:05:43.680657 File system: filesystemCheckLunImage(): Checking for (.ucd) LUN user code descriptor
Tue,14 Jan 2020.00:05:43.680696 File system: filesystemCheckLunImage(): LUN user code descriptor not found
Tue,14 Jan 2020.00:05:43.680733 File system: filesystemCheckLunImage(): Successful
Tue,14 Jan 2020.00:05:43.680769
Tue,14 Jan 2020.00:05:43.680805
Tue,14 Jan 2020.00:05:43.680841 SCSI State: Resetting SCSI emulation
Tue,14 Jan 2020.00:05:43.680877 SCSI State: Firmware: V002.005
Tue,14 Jan 2020.00:05:43.680913 Emulation mode is Winchester (ADFS SCSI-1 hard-drive)
Tue,14 Jan 2020.00:05:43.680948
Tue,14 Jan 2020.00:05:43.680984 SCSI State: Bus Free
Tue,14 Jan 2020.00:05:43.681020 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:05:43.768550 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:05:43.768661 SCSI State: Command phase
Tue,14 Jan 2020.00:05:43.768702 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:05:43.768740 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:05:43.768776 SCSI Commands: Received command operand bytes: 8 0 0 0 2 0
Tue,14 Jan 2020.00:05:43.768813 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:05:43.768849 SCSI Commands: Target LUN = 0, LBA = 0, Blocks = 2
Tue,14 Jan 2020.00:05:43.768885 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:05:43.768927 File system: filesystemOpenLunForRead(): Flushing the file system
Tue,14 Jan 2020.00:05:43.850905 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:05:43.851014 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:05:43.851054 0 1
Tue,14 Jan 2020.00:05:43.851091 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:05:43.851128 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:05:43.851164 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:05:43.851201 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:05:43.851237 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:05:43.851273 SCSI State: Bus Free
Tue,14 Jan 2020.00:05:43.851309 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:05:43.851345 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:05:43.935144 SCSI State: Command phase
Tue,14 Jan 2020.00:05:43.935249 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:05:43.935288 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:05:43.935324 SCSI Commands: Received command operand bytes: 8 0 0 2 5 0
Tue,14 Jan 2020.00:05:43.935361 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:05:43.935397 SCSI Commands: Target LUN = 0, LBA = 2, Blocks = 5
Tue,14 Jan 2020.00:05:43.935433 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:05:43.935469 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:05:43.935505 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:05:43.935541 0 1 2 3 4
Tue,14 Jan 2020.00:05:43.935577 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:05:44.024158 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:05:44.024358 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:05:44.024487 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:05:44.024599 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:05:44.024700 SCSI State: Bus Free
Tue,14 Jan 2020.00:05:44.024794 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:05:44.024885 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:05:44.024974 SCSI State: Command phase
Tue,14 Jan 2020.00:05:44.025062 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:05:44.025149 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:05:44.025238 SCSI Commands: Received command operand bytes: 8 0 0 0 2 0
Tue,14 Jan 2020.00:05:44.108474 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:05:44.108674 SCSI Commands: Target LUN = 0, LBA = 0, Blocks = 2
Tue,14 Jan 2020.00:05:44.108799 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:05:44.108909 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:05:44.109014 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:05:44.109109 0 1
Tue,14 Jan 2020.00:05:44.109203 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:05:44.109293 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:05:44.109382 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:05:44.109471 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:05:44.109560 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:05:44.139205 SCSI State: Bus Free
Tue,14 Jan 2020.00:05:44.139332 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:05:44.139379 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:05:44.223364 SCSI State: Command phase
Tue,14 Jan 2020.00:05:44.223476 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:05:44.223523 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:05:44.223576 SCSI Commands: Received command operand bytes: 8 0 0 2 5 0
Tue,14 Jan 2020.00:05:44.223619 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:05:44.223659 SCSI Commands: Target LUN = 0, LBA = 2, Blocks = 5
Tue,14 Jan 2020.00:05:44.223698 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:05:44.223738 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:05:44.223777 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:05:44.223816 0 1 2 3 4
Tue,14 Jan 2020.00:05:44.312500 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:05:44.312655 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:05:44.312770 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:05:44.312855 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:05:44.312937 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:05:44.313015 SCSI State: Bus Free
Tue,14 Jan 2020.00:05:44.313093 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:05:44.313170 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:05:44.313246 SCSI State: Command phase
Tue,14 Jan 2020.00:05:44.313322 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:05:44.313398 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:05:44.396822 SCSI Commands: Received command operand bytes: 8 0 0 0 2 0
Tue,14 Jan 2020.00:05:44.396965 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:05:44.397046 SCSI Commands: Target LUN = 0, LBA = 0, Blocks = 2
Tue,14 Jan 2020.00:05:44.397126 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:05:44.397210 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:05:44.397291 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:05:44.397368 0 1
Tue,14 Jan 2020.00:05:44.397445 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:05:44.397522 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:05:44.397598 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:05:44.397676 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:05:44.397753 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:05:44.425446 SCSI State: Bus Free
Tue,14 Jan 2020.00:05:44.425546 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:05:44.425587 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:05:44.509745 SCSI State: Command phase
Tue,14 Jan 2020.00:05:44.509843 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:05:44.509885 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:05:44.509926 SCSI Commands: Received command operand bytes: 8 0 0 2 5 0
Tue,14 Jan 2020.00:05:44.509968 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:05:44.510012 SCSI Commands: Target LUN = 0, LBA = 2, Blocks = 5
Tue,14 Jan 2020.00:05:44.510052 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:05:44.510091 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:05:44.510130 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:05:44.510170 0 1 2 3 4
Tue,14 Jan 2020.00:05:44.567606 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:05:44.567701 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:05:44.567742 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:05:44.567782 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:05:44.567824 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:05:44.567867 SCSI State: Bus Free
Tue,14 Jan 2020.00:05:44.567905 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:06:01.257691 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:06:01.341991 SCSI State: Command phase
Tue,14 Jan 2020.00:06:01.342147 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:06:01.342223 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:06:01.342297 SCSI Commands: Received command operand bytes: 8 0 0 0 2 0
Tue,14 Jan 2020.00:06:01.342371 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:06:01.342443 SCSI Commands: Target LUN = 0, LBA = 0, Blocks = 2
Tue,14 Jan 2020.00:06:01.342515 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:06:01.342586 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:06:01.342658 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:06:01.342730 0 1
Tue,14 Jan 2020.00:06:01.342801 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:06:01.426283 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:06:01.426390 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:06:01.426429 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:06:01.426465 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:06:01.426502 SCSI State: Bus Free
Tue,14 Jan 2020.00:06:01.426538 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:06:01.426573 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:06:01.426609 SCSI State: Command phase
Tue,14 Jan 2020.00:06:01.426645 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:06:01.426681 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:06:01.426717 SCSI Commands: Received command operand bytes: 8 31 22 98 3 0
Tue,14 Jan 2020.00:06:01.462894 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:06:01.463037 SCSI Commands: Target LUN = 0, LBA = 2037346, Blocks = 3
Tue,14 Jan 2020.00:06:01.463077 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:06:02.479678 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:06:02.479883 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:06:02.479997 0 1 2
Tue,14 Jan 2020.00:06:02.480107 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:06:02.480215 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:06:02.480390 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:06:02.480501 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:06:02.480608 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:06:02.480714 SCSI State: Bus Free
Tue,14 Jan 2020.00:06:02.480821 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:06:02.480928 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:06:02.481035 SCSI State: Command phase
Tue,14 Jan 2020.00:06:02.564034 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:06:02.564430 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:06:02.564725 SCSI Commands: Received command operand bytes: 8 31 22 101 1 0
Tue,14 Jan 2020.00:06:02.565000 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:06:02.565267 SCSI Commands: Target LUN = 0, LBA = 2037349, Blocks = 1
Tue,14 Jan 2020.00:06:02.565530 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:06:02.565793 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:06:02.566057 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:06:02.566326 0
Tue,14 Jan 2020.00:06:02.566589 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:06:02.566852 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:06:02.611145 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:06:02.611496 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:06:02.611771 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:06:02.612002 SCSI State: Bus Free
Tue,14 Jan 2020.00:06:02.612211 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:06:12.513865 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:06:12.514298 SCSI State: Command phase
Tue,14 Jan 2020.00:06:12.514622 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:06:12.514929 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:06:12.515220 SCSI Commands: Received command operand bytes: 8 31 0 0 16 0
Tue,14 Jan 2020.00:06:12.515491 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:06:12.515758 SCSI Commands: Target LUN = 0, LBA = 2031616, Blocks = 16
Tue,14 Jan 2020.00:06:12.516027 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:06:13.490833 File system: filesystemOpenLunForRead(): Successful

Tue,14 Jan 2020.00:06:13.579953 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:06:13.580241 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15
Tue,14 Jan 2020.00:06:13.580500 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:06:13.580701 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:06:13.580898 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:06:13.581081 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:06:13.581264 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:06:13.581443 SCSI State: Bus Free
Tue,14 Jan 2020.00:06:13.581620 SCSI State: Information transfer phase: Data out
The actual fetching from the FAT file takes nearly a second. Most of that occurs during f_lseek.

In fact, for some reason, the fastseek portion of code wasn't being compiled in filesystem.c:

Code: Select all

#if FF_USE_FASTSEEK
			((FIL*)(&filesystemState.fileObject))->cltbl = clmt;
			filesystemState.fsResult  = f_lseek(&filesystemState.fileObject, CREATE_LINKMAP);
#endif
Since fastseek is enabled in ffcode.h, we shouldn't need conditional compilation, so I just commented out the if & endif.

Re-compiled as version 2.6 and did my read from &1F0000 again:
BeebSCSI 2.6 wrote:Tue,14 Jan 2020.00:12:16.416891
Tue,14 Jan 2020.00:12:16.463567 BeebSCSI - Acorn SCSI-1 Emulation
Tue,14 Jan 2020.00:12:16.463807
Tue,14 Jan 2020.00:12:16.463938 (c)2018-2019 Simon Inns
Tue,14 Jan 2020.00:12:16.464080 https://www.domesday86.com
Tue,14 Jan 2020.00:12:16.464209 Open-source GPLv3 firmware
Tue,14 Jan 2020.00:12:16.464334
Tue,14 Jan 2020.00:12:16.464459 Firmware: V002.006
Tue,14 Jan 2020.00:12:16.464581 Emulation mode is Winchester (ADFS SCSI-1 hard-drive)
Tue,14 Jan 2020.00:12:16.464704 USB capable board not detected
Tue,14 Jan 2020.00:12:16.464822
Tue,14 Jan 2020.00:12:24.167863 File system: filesystemReset(): Resetting file system
Tue,14 Jan 2020.00:12:24.252283 File system: filesystemReset(): File system is flagged as mounted
Tue,14 Jan 2020.00:12:24.252741 File system: filesystemCheckLunImage(): Flushing the file system
Tue,14 Jan 2020.00:12:24.252925 File system: filesystemCheckLunImage(): Checking for (.dat) LUN image 0
Tue,14 Jan 2020.00:12:24.253049 File system: filesystemCheckLunImage(): LUN image found
Tue,14 Jan 2020.00:12:24.253171 File system: filesystemCheckLunImage(): LUN size in bytes (according to .dat) = 553648128
Tue,14 Jan 2020.00:12:24.253290 File system: filesystemCheckLunImage(): WARNING: The LUN file size is greater than 512Mbs
Tue,14 Jan 2020.00:12:24.336339 File system: filesystemCheckLunImage(): Checking for (.dsc) LUN descriptor 0
Tue,14 Jan 2020.00:12:24.336437 File system: filesystemCheckLunImage(): LUN descriptor found
Tue,14 Jan 2020.00:12:24.336478 File system: filesystemGetLunSizeFromDsc(): Flushing the file system
Tue,14 Jan 2020.00:12:24.336519 File system: LUN Descriptor contents:
Tue,14 Jan 2020.00:12:24.336559 File system: Mode Select Parameter List:
Tue,14 Jan 2020.00:12:24.336600 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:12:24.336640 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:12:24.336681 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:12:24.336723 File system: Length of Extent Descriptor List (8) = 8
Tue,14 Jan 2020.00:12:24.336763 File system: Extent Descriptor List:
Tue,14 Jan 2020.00:12:24.336803 File system: Density code = 0
Tue,14 Jan 2020.00:12:24.420660 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:12:24.420759 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:12:24.420799 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:12:24.420839 File system: Reserved (0) = 0
Tue,14 Jan 2020.00:12:24.420879 File system: Block size = 256
Tue,14 Jan 2020.00:12:24.420918 File system: Drive Parameter List:
Tue,14 Jan 2020.00:12:24.420958 File system: List format code = 1
Tue,14 Jan 2020.00:12:24.421005 File system: Cylinder count = 1024
Tue,14 Jan 2020.00:12:24.421046 File system: Data head count = 64
Tue,14 Jan 2020.00:12:24.421087 File system: Reduced write current cylinder = 128
Tue,14 Jan 2020.00:12:24.421128 File system: Write pre-compensation cylinder = 128
Tue,14 Jan 2020.00:12:24.421168 File system: Landing zone position = 0
Tue,14 Jan 2020.00:12:24.421208 File system: Step pulse output rate code = 1
Tue,14 Jan 2020.00:12:24.504961 File system: filesystemCheckLunImage(): LUN size in bytes (according to .dsc) = 553648128
Tue,14 Jan 2020.00:12:24.505065 File system: filesystemCheckLunImage(): Checking for (.ucd) LUN user code descriptor
Tue,14 Jan 2020.00:12:24.505105 File system: filesystemCheckLunImage(): LUN user code descriptor not found
Tue,14 Jan 2020.00:12:24.505146 File system: filesystemCheckLunImage(): Successful
Tue,14 Jan 2020.00:12:24.505188
Tue,14 Jan 2020.00:12:24.505231
Tue,14 Jan 2020.00:12:24.505275 SCSI State: Resetting SCSI emulation
Tue,14 Jan 2020.00:12:24.505316 SCSI State: Firmware: V002.006
Tue,14 Jan 2020.00:12:24.505358 Emulation mode is Winchester (ADFS SCSI-1 hard-drive)
Tue,14 Jan 2020.00:12:24.505398
Tue,14 Jan 2020.00:12:24.505438 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:24.505478 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:24.594186 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:24.594283 SCSI State: Command phase
Tue,14 Jan 2020.00:12:24.594323 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:24.594362 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:24.594402 SCSI Commands: Received command operand bytes: 8 0 0 0 2 0
Tue,14 Jan 2020.00:12:24.594444 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:24.594488 SCSI Commands: Target LUN = 0, LBA = 0, Blocks = 2
Tue,14 Jan 2020.00:12:24.594530 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:24.594570 File system: filesystemOpenLunForRead(): Flushing the file system
Tue,14 Jan 2020.00:12:25.188832 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:25.188978 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:25.189053 0 1
Tue,14 Jan 2020.00:12:25.189125 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:25.189197 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:25.189268 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:25.189340 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:25.189412 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:25.189483 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:25.189555 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:25.277694 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:25.277846 SCSI State: Command phase
Tue,14 Jan 2020.00:12:25.277921 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:25.277994 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:25.278065 SCSI Commands: Received command operand bytes: 8 0 0 2 5 0
Tue,14 Jan 2020.00:12:25.278137 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:25.278208 SCSI Commands: Target LUN = 0, LBA = 2, Blocks = 5
Tue,14 Jan 2020.00:12:25.278280 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:25.278351 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:25.278422 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:25.365693 0 1 2 3 4
Tue,14 Jan 2020.00:12:25.365803 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:25.365842 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:25.365879 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:25.365915 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:25.365951 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:25.365986 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:25.366022 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:25.366058 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:25.366093 SCSI State: Command phase
Tue,14 Jan 2020.00:12:25.366129 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:25.366165 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:25.450015 SCSI Commands: Received command operand bytes: 8 0 0 0 2 0
Tue,14 Jan 2020.00:12:25.450123 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:25.450162 SCSI Commands: Target LUN = 0, LBA = 0, Blocks = 2
Tue,14 Jan 2020.00:12:25.450199 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:25.450235 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:25.450302 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:25.450342 0 1
Tue,14 Jan 2020.00:12:25.450378 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:25.450414 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:25.450449 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:25.450485 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:25.476300 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:25.476434 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:25.476478 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:25.562865 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:25.562973 SCSI State: Command phase
Tue,14 Jan 2020.00:12:25.563011 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:25.563048 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:25.563084 SCSI Commands: Received command operand bytes: 8 0 0 2 5 0
Tue,14 Jan 2020.00:12:25.563120 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:25.563155 SCSI Commands: Target LUN = 0, LBA = 2, Blocks = 5
Tue,14 Jan 2020.00:12:25.563191 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:25.563226 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:25.563262 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:25.650875 0 1 2 3 4
Tue,14 Jan 2020.00:12:25.650983 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:25.651021 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:25.651058 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:25.651094 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:25.651129 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:25.651166 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:25.651201 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:25.651237 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:25.651273 SCSI State: Command phase
Tue,14 Jan 2020.00:12:25.651308 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:25.651344 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:25.735206 SCSI Commands: Received command operand bytes: 8 0 0 0 2 0
Tue,14 Jan 2020.00:12:25.735528 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:25.735709 SCSI Commands: Target LUN = 0, LBA = 0, Blocks = 2
Tue,14 Jan 2020.00:12:25.735862 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:25.736013 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:25.736161 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:25.736308 0 1
Tue,14 Jan 2020.00:12:25.736454 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:25.736601 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:25.736746 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:25.736888 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:25.761604 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:25.761837 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:25.761943 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:25.849396 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:25.849600 SCSI State: Command phase
Tue,14 Jan 2020.00:12:25.849729 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:25.849841 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:25.849943 SCSI Commands: Received command operand bytes: 8 0 0 2 5 0
Tue,14 Jan 2020.00:12:25.850037 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:25.850130 SCSI Commands: Target LUN = 0, LBA = 2, Blocks = 5
Tue,14 Jan 2020.00:12:25.850219 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:25.850351 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:25.850455 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:25.906705 0 1 2 3 4
Tue,14 Jan 2020.00:12:25.906911 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:25.907032 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:25.907137 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:25.907237 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:25.907330 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:25.907422 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:25.907541 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:34.091552 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:34.175743 SCSI State: Command phase
Tue,14 Jan 2020.00:12:34.175965 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:34.176093 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:34.176202 SCSI Commands: Received command operand bytes: 8 0 0 0 2 0
Tue,14 Jan 2020.00:12:34.176306 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:34.176404 SCSI Commands: Target LUN = 0, LBA = 0, Blocks = 2
Tue,14 Jan 2020.00:12:34.176498 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:34.176591 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:34.176682 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:34.176772 0 1
Tue,14 Jan 2020.00:12:34.176861 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:34.235715 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:34.235922 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:34.236042 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:34.236147 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:34.236245 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:34.236338 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:34.236428 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:34.236517 SCSI State: Command phase
Tue,14 Jan 2020.00:12:34.320038 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:34.320244 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:34.320408 SCSI Commands: Received command operand bytes: 8 31 22 98 3 0
Tue,14 Jan 2020.00:12:34.320518 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:34.320621 SCSI Commands: Target LUN = 0, LBA = 2037346, Blocks = 3
Tue,14 Jan 2020.00:12:34.320715 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:34.320807 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:34.320897 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:34.320986 0 1 2
Tue,14 Jan 2020.00:12:34.321075 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:34.407542 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:34.407748 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:34.407864 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:34.407968 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:34.408072 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:34.408164 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:34.408255 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:34.408344 SCSI State: Command phase
Tue,14 Jan 2020.00:12:34.408432 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:34.408521 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:34.491880 SCSI Commands: Received command operand bytes: 8 31 22 101 1 0
Tue,14 Jan 2020.00:12:34.492081 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:34.492190 SCSI Commands: Target LUN = 0, LBA = 2037349, Blocks = 1
Tue,14 Jan 2020.00:12:34.492291 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:34.492388 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:34.492482 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:34.492583 0
Tue,14 Jan 2020.00:12:34.492674 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:34.492764 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:34.492853 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:34.492941 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:34.493030 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:34.517984 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:34.518188 SCSI State: Information transfer phase: Data out
Tue,14 Jan 2020.00:12:39.835786 SCSI State: Selected by host ID 1
Tue,14 Jan 2020.00:12:39.851815 SCSI State: Command phase
Tue,14 Jan 2020.00:12:39.883879 SCSI State: Information transfer phase: Command
Tue,14 Jan 2020.00:12:39.970065 SCSI Commands: CDB byte 0 decode: Command group 0 (6 bytes) opcode 8
Tue,14 Jan 2020.00:12:39.970303 SCSI Commands: Received command operand bytes: 8 31 0 0 16 0
Tue,14 Jan 2020.00:12:39.970428 SCSI Commands: READ command (0x08) received
Tue,14 Jan 2020.00:12:39.970534 SCSI Commands: Target LUN = 0, LBA = 2031616, Blocks = 16
Tue,14 Jan 2020.00:12:39.970631 SCSI State: Information transfer phase: Data in
Tue,14 Jan 2020.00:12:39.970725 File system: filesystemOpenLunForRead(): Successful
Tue,14 Jan 2020.00:12:39.970819 SCSI Commands: Transferring requested blocks to the host...
Tue,14 Jan 2020.00:12:39.970908 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15
Tue,14 Jan 2020.00:12:39.970996 SCSI Commands: Read6 command successful
Tue,14 Jan 2020.00:12:40.017191 SCSI State: Status. Status byte = 0
Tue,14 Jan 2020.00:12:40.017994 SCSI State: Information transfer phase: Status
Tue,14 Jan 2020.00:12:40.018660 SCSI State: Message In. Message byte = 0
Tue,14 Jan 2020.00:12:40.019311 SCSI State: Information transfer phase: Message in
Tue,14 Jan 2020.00:12:40.019487 SCSI State: Bus Free
Tue,14 Jan 2020.00:12:40.019611 SCSI State: Information transfer phase: Data out
...and the FAT read operation now takes just 94ms.

My file server *EX now takes under 5 seconds.

I've attached the scsi.c (just version number change) and filesystem.c files which I altered, and a new BEEBSCSI.BIN. Incidentally I found it doesn't work from an exFAT card, I had to use my previous FAT32 card to update the firmware!
Attachments
BEEBSCSI.BIN.zip
(36.73 KiB) Downloaded 1 time
filesystem.c
(69.84 KiB) Downloaded 2 times
scsi.c
(84.54 KiB) Downloaded 1 time
Image

User avatar
simoni
Posts: 498
Joined: Wed May 25, 2016 6:18 pm
Contact:

Re: BeebSCSI 7_7

Post by simoni » Tue Jan 14, 2020 5:00 am

Looks good! Can you attach your test code so I can recreate your test conditions? I'll take a look at the change and check for regression. If there are no side-effects I'll push a new software version.

As for exFAT support... BeebSCSI supports it. However, the bootloader (used to upgrade BeebSCSI) is a separate program and has to be kept really small, so it only supports FAT (hence you needing a smaller card to perform the upgrade). To quote the documentation:

"In order to program the AVR firmware you will need a micro SD card formatted using FAT32 (i.e. 32GBs or less and formatted using FAT32 on a Windows or Linux PC). It is preferable to use a blank card."

In the future, if you push a non-version tracked build (i.e. not from the github) - don't give it a release version (go for 000.001 or something) - otherwise, if it has regressions in it and someone upgrades, I'll never be able to spot that the firmware is odd from the debug :)

User avatar
hoglet
Posts: 8776
Joined: Sat Oct 13, 2012 6:21 pm
Location: Bristol
Contact:

Re: BeebSCSI 7_7

Post by hoglet » Tue Jan 14, 2020 7:48 am

I think an old version of FATFS is being used in BeebSCSI; the symbol seems to be called _USE_FASTSEEK not FF_USE_FASTSEEK
https://github.com/simoninns/BeebSCSI/b ... conf.h#L46

See also this post:
viewtopic.php?p=229567#p229567

Dave

User avatar
simoni
Posts: 498
Joined: Wed May 25, 2016 6:18 pm
Contact:

Re: BeebSCSI 7_7

Post by simoni » Tue Jan 14, 2020 8:47 am

It might be a regression from the last fix of BeebSCSI then - it was a while ago, but I think the push request changed things in the FATFS library. It might be that the library was upgraded a bit, but the symbol wasn't updated... I need to take a look at the code and work out what's what. The idea of the code structure was to keep the FATFS library adjunct and unchanged (otherwise upgrading it is difficult) - so deleting conditional compile statements in the library is probably not the optimum response. Generally, with embedded software, I like to keep the libraries as-is unless there is a significant reason to upgrade them. Regression testing is extremely time consuming :)

When I have some time, I'll look into it and update the github.

dp11
Posts: 967
Joined: Sun Aug 12, 2012 8:47 pm
Contact:

Re: BeebSCSI 7_7

Post by dp11 » Tue Jan 14, 2020 10:32 am

Looks like a recent version of ffconf.h hasn't been checked in.

Though I haven't tested Pi1MHz build the code base for Pi1MHz looks okay.

User avatar
hoglet
Posts: 8776
Joined: Sat Oct 13, 2012 6:21 pm
Location: Bristol
Contact:

Re: BeebSCSI 7_7

Post by hoglet » Tue Jan 14, 2020 10:50 am

I think what's caused confusion here is that that FatFS effectively changed their configuration API:

Code: Select all

R0.13 (May 21, 2017)
  Changed heading character of configuration keywords "_" to "FF_".
(I'm using the term API rather loosely here)

Simon's "upstream" BeebSCSI uses an R0.12b of FatFS.

Dominic's "downstream" Pi1MHz uses R0.13c of FatFS.

This fix was initially tested against the version of BeebSCSI in Pi1MHz, which uses the FF_ version of the #define.

When it was merged to the "upstream" version of BeebSCSI with the older FatFS, it seems #define was never changed, not was FastFS updated. So in this context I don't think it ever can have worked.

This isn't so much a regression (due to unsupportable patches to FatFS code), rather it's because changes to FatFS itself.

Dave

User avatar
BeebMaster
Posts: 2962
Joined: Sun Aug 02, 2009 4:59 pm
Location: Lost in the BeebVault!
Contact:

Re: BeebSCSI 7_7

Post by BeebMaster » Tue Jan 14, 2020 11:26 am

Yes, it was never intended as a release version as such, just a way I could distinguish between 2.5 and the test versions I was using (which I'd called 2.99 until this fix). That's why I put it here rather than doing anything to github.

It's probably better to keep the original conditional compiling with the correct definition, what I did is just a proof that fastseek wasn't working in 2.5.

Here's the test code (although the loop isn't necessary, that was introduced for testing around the previous problem where repeat reads progressively slowed down, but that was fixed in 2.4 or 2.3):

Code: Select all

   10REM OSWORD Read Test
   20REM Repeated load fixed sector
   30REM using OSWORD &72
   40REM 28/i/19
   50DIM osblock 256
   60drive%=0
   70result%=&4000
   80sectors%=&10
   90REMstep%=&2000:Not usedin RDFix
  100A%=&72
  110X%=osblock MOD 256
  120Y%=osblock DIV 256
  130REPEAT
  135start%=&1F0000
  140?osblock=0:REM complete code will go here on exit from call
  150osblock!1=result%:REM result block
  160osblock?5=&8:REM command code
  170osblock?6=start% DIV 65536:REM MSB of start sector in low 5 bits
  180osblock?6=osblock?6+32*drive%:REM drive number is in top 3 bits
  190osblock?7=start% DIV 256 MOD 256:REM middle byte of start sector
  200osblock?8=start% MOD 256:REM LSB of start sector
  210osblock?9=sectors%:REM sectors to read
  220osblock?10=0:REM reserved
  230TIME=0
  240CALL&FFF1
  250PRINT"Read from :";drive%;"/";STRING$(6-LENSTR$~start%,"0");~start%;" in ";TIME;" cs"TAB(30)TIME$;" - ";
  260IF?osblock PRINT"Error &";~?osblock ELSEPRINT"OK"
  270UNTIL0
Incidentally one side-effect is that opening a LUN for the first time with *ADFS or *MOUNT now takes around a second as the cluster table thingy is built for fastseek when opening a LUN for read, and I just noticed that the *SPOOL I used to list that code seemed to take longer than I would expect - I think that is probably because it calls the fastseek setup again when opening a LUN for write - I'm not sure whether that is needed in both cases?
Image

User avatar
BeebMaster
Posts: 2962
Joined: Sun Aug 02, 2009 4:59 pm
Location: Lost in the BeebVault!
Contact:

Re: BeebSCSI 7_7

Post by BeebMaster » Wed Jan 15, 2020 11:32 pm

I looked into this more. I found that every write operation was re-opening the LUN, and thereby setting up the fastseek link table, which was introducing a delay. Here's the culprit from filesystem.c:

Code: Select all

...
// Function to open a LUN ready for writing
bool filesystemOpenLunForWrite(uint8_t lunNumber, uint32_t startSector, uint32_t requiredNumberOfSectors)
{
	// Ensure there isn't already a LUN image open
	if (lunOpenFlag) {
		// check that it is the same LUN Number 
      	if (filesystemState.lunNumber != lunNumber)
			if (debugFlag_filesystem) debugString_P(PSTR("File system: filesystemOpenLunForWrite(): Flushing the file system\r\n"));
         	filesystemFlush();
	}
...
There's a set of curly brackets missing, so it's always calling filesystemFlush(), which closes the LUN, and the code then goes on to check if it's open and naturally opens it again as it finds it isn't already open. All we need is extra curly brackets:

Code: Select all

...
// Function to open a LUN ready for writing
bool filesystemOpenLunForWrite(uint8_t lunNumber, uint32_t startSector, uint32_t requiredNumberOfSectors)
{
	// Ensure there isn't already a LUN image open
	if (lunOpenFlag) {
		// check that it is the same LUN Number 
      	if (filesystemState.lunNumber != lunNumber) {
	if (debugFlag_filesystem) debugString_P(PSTR("File system: filesystemOpenLunForWrite(): Flushing the file system\r\n"));
         	filesystemFlush();
	}
	}
...	
and then it works perfectly, a repeat read...write loop doesn't have any time lag at all, and spool works correctly.

So I think this is the only change in fact needed at all, plus the update to the conditional compiling to reference the correct variable for fastseek.

[As yet another aside, it's interesting to watch the debug output to see what ADFS is actually doing, and some of it is decidedly curious.

On a mount, ADFS reads the FS map then the root directory 3 times in succession. No idea why it might do that.

On any file read operation (LOAD, DIR etc) ADFS reads the FS map again first, but doesn't do that on a direct sector read. Presumably it does that to check the map hasn't gone bad somehow since it was last read.

To load a file it fetches all but the last block in one go, and then as a separate read operation it fetches the last block. Presumably it has a way of truncating the last sector so it doesn't fetch the bytes in the sector which are beyond the end of the file.]
Image

dp11
Posts: 967
Joined: Sun Aug 12, 2012 8:47 pm
Contact:

Re: BeebSCSI 7_7

Post by dp11 » Thu Jan 16, 2020 4:34 pm

Thanks , now fixed on the Pi1MHz build. I'll look at updating to the latest version of FatFS at some point as it have some exFAT fixes.

Post Reply