performance of flashrom (with FT2232H)

[Amelkin, Aleksandr]

I noticed that it takes painfully long for flashrom to even simply read a 16MB flash chip
using FT2232H (Olimex ARM-USB-TINY-H) programmer.

The time it takes would be appropriate for kHz-range SPI clocks, not for 30MHz SPI clock
that FT2232H provides.

I checked with an oscilloscope and found out that there are long multi-millisecond delays between short (~150us) SPI clock bursts during simple chip read operation ('-r' or 'reading old flash chip contents'). The delays are 2ms for native Windows 7 64-bit on an Intel Core-i7 2600 @ 3.4GHz, or as long as 7ms for a Ubuntu Linux running in a virtual box on the same Windows machine.

I didn't look any deeper though.

Has anyone done any profiling or have any ideas as to what may be causing this behavior?

With best regards,
Alexander Amelkin.

[Stefan Tauner]

On Wed, 14 Jan 2015 16:23:32 +0300
"Amelkin,  Aleksandr"  wrote:
> I noticed that it takes painfully long for flashrom to even simply read a 16MB flash chip
> using FT2232H (Olimex ARM-USB-TINY-H) programmer.
>
> The time it takes would be appropriate for kHz-range SPI clocks, not for 30MHz SPI clock
> that FT2232H provides.
>
> I checked with an oscilloscope and found out that there are long multi-millisecond delays between short (~150us) SPI clock bursts during simple chip read operation ('-r' or 'reading old flash chip contents'). The delays are 2ms for native Windows 7 64-bit on an Intel Core-i7 2600 @ 3.4GHz, or as long as 7ms for a Ubuntu Linux running in a virtual box on the same Windows machine.
>
> I didn't look any deeper though.
>
> Has anyone done any profiling or have any ideas as to what may be causing this behavior?

I suspect the main part of this is the latency of the (FTDI) USB
protocol. Maybe the performance of the flashrom driver can be improved
with bigger buffers/bursts of reads but I am not aware of any obvious
bottlenecks.

[Amelkin, Aleksandr]

> > I noticed that it takes painfully long for flashrom to even simply
> > read a 16MB flash chip using FT2232H (Olimex ARM-USB-TINY-H)
>
> programmer.
> > The time it takes would be appropriate for kHz-range SPI clocks, not
> > for 30MHz SPI clock that FT2232H provides.
> >
> > I checked with an oscilloscope and found out that there are long multi-
>
> millisecond delays between short (~150us) SPI clock bursts during simple chip
> read operation ('-r' or 'reading old flash chip contents'). The delays are 2ms
> for native Windows 7 64-bit on an Intel Core-i7 2600 @ 3.4GHz, or as long as
> 7ms for a Ubuntu Linux running in a virtual box on the same Windows
> machine.
> > I didn't look any deeper though.
> >
> > Has anyone done any profiling or have any ideas as to what may be causing
>
> this behavior?
>
> I suspect the main part of this is the latency of the (FTDI) USB protocol.
> Maybe the performance of the flashrom driver can be improved with bigger
> buffers/bursts of reads but I am not aware of any obvious bottlenecks.

Stefan, you are correct. It doesn't look like flashrom's fault.

I did some profiling and found out that ft2232_spi_send_command() is called
during the chip read operation with a delay of just around 50us after itself.
Inside the function there are 2 to send_buf() and 1 call to get_buf() that altogether
total to those damn 7ms. Digging further gave me that the majority of the time
for send_buf() is spent inside ftdi_write_data() which is basically a wrapper around
usb_bulk_write().

According to profiling data, the only function that usb_bulk_write() calls is ioctl(),
and those 4 calls per bulk write call take just as much as 7% of the total time taken
by usb_bulk_write().

Since usb_bulk_write() is nothing more than a loop calling:

ioctl(dev->fd, IOCTL_USB_BULK, &bulk);

I assume that the poor performance is the fault of FT2232H itself.

Does it sound to you  like my analysis is correct or am I terribly wrong anywhere?

Thanks.

With best regards –
Alexander Amelkin,
T-Platforms [http://www.t-platforms.com]