daniel-santos / mcp2210-linux

MCP2210 driver for linux
http://danielthesantos.blogspot.com/search/label/mcp2210
51 stars 31 forks source link

slow transfer speeds #11

Open mweal-ed opened 10 years ago

mweal-ed commented 10 years ago

I am trying to speed up the transfer speeds as they seem to be at lot slower than I expected (4096 bytes in .77 seconds or 43Kbps vs 4-6Mbps) I would expect it to be a couple of orders faster than this. I know some of the problems is due to the overhead on the USB bus. I was wondering if you could point me in the in the right direction to fix this.

The first issue I have found is drivers looks like it is breaking up the transfer rather oddly. It is breaking up large transfers into 60 byte and 4 byte transfers alternately rather than all 60 byte transfers. I can see where spi_submit_prepare restricts it to 60 bytes transfers but have not found where the messages are restricted to 4 byte transfers.

I am developing on ubuntu 14.04 x86_64 the following is a snippet from the syslog.

   usb 2-1.3: queue_msg: Start new transfer (pin 0)
Jun 25 13:47:20 dev906 kernel: [11265.697389] usb 2-1.3: process_commands: 
Jun 25 13:47:20 dev906 kernel: [11265.697394] usb 2-1.3: process_delayed_list: 
Jun 25 13:47:20 dev906 kernel: [11265.697398] usb 2-1.3: process_delayed_list: next =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.697403] usb 2-1.3: process_commands: got a command (ffff8800a2348a80)
Jun 25 13:47:20 dev906 kernel: [11265.697412] usb 2-1.3: submit_urbs: 
Jun 25 13:47:20 dev906 kernel: [11265.697421] usb 2-1.3: spi_submit_prepare: pin 0
Jun 25 13:47:20 dev906 kernel: [11265.697429] usb 2-1.3: spi_prepare_device: dev->s.cur_spi_config = 0
Jun 25 13:47:20 dev906 kernel: [11265.697489] dev->s.spi_settings = ffff8800a22eb9d0 struct mcp2210_spi_xfer_setting {
Jun 25 13:47:20 dev906 kernel: [11265.697489]   .bitrate               = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.697489]   .idle_cs               = 0x0001
Jun 25 13:47:20 dev906 kernel: [11265.697489]   .active_cs             = 0x0000
Jun 25 13:47:20 dev906 kernel: [11265.697489]   .cs_to_data_delay      = 0x0001
Jun 25 13:47:20 dev906 kernel: [11265.697489]   .last_byte_to_cs_delay = 0x0001
Jun 25 13:47:20 dev906 kernel: [11265.697489]   .delay_between_bytes   = 0x0001
Jun 25 13:47:20 dev906 kernel: [11265.697489]   .bytes_per_trans       = 0x1000
Jun 25 13:47:20 dev906 kernel: [11265.697489]   .mode                  = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.697489] }
Jun 25 13:47:20 dev906 kernel: [11265.697528] usb 2-1.3: spi_submit_prepare: sending 60 bytes
Jun 25 13:47:20 dev906 kernel: [11265.697537] usb 2-1.3: spi_submit_prepare: len: 60, cmd->pending_bytes: 60
Jun 25 13:47:20 dev906 kernel: [11265.697545] submit_urbs: cmd = ffff8800a2348a80 struct mcp2210_cmd_type_spi {
Jun 25 13:47:20 dev906 kernel: [11265.697563]   .head = ffff8800a2348a80 struct mcp2210_cmd {
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .dev            = ffff8800a22eb800
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .type           = ffffffffa0415ba0 (spi)
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .node           = ffff8800a2348a90 struct list_head {.next = dead000000100100, .prev = dead000000200200}
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .time_queued    = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .time_started   = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .delay_until    = 0
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .status         = -115
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .mcp_status     = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .state          = 0 ()
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .can_retry      = 0
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .delayed        = 0
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .nonatomic      = 0
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .repeat_count   = 0
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .complete       = ffffffffa040de20
Jun 25 13:47:20 dev906 kernel: [11265.697563]     .context        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.697563]   }
Jun 25 13:47:20 dev906 kernel: [11265.697603]   .spi = ffff880135e21c00 struct spi_device {
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .dev
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .master           = ffff8800a22ea800
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .max_speed_hz     = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .chip_select      = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .mode             = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .bits_per_word    = 0x08
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .irq              = 0
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .controller_state =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .controller_data  =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.697603]     .modalias         = fb_ssd1351
Jun 25 13:47:20 dev906 kernel: [11265.697603]   }
Jun 25 13:47:20 dev906 kernel: [11265.697664]   .msg = ffff8801358c5c60 struct spi_message {
Jun 25 13:47:20 dev906 kernel: [11265.697664]     .transfers     = {.next = ffff8801358c5c50, .prev = ffff8801358c5c50}
Jun 25 13:47:20 dev906 kernel: [11265.697664]     .spi           = ffff880135e21c00
Jun 25 13:47:20 dev906 kernel: [11265.697664]     .is_dma_mapped = 0
Jun 25 13:47:20 dev906 kernel: [11265.697664]     .complete      = ffffffff81515d40
Jun 25 13:47:20 dev906 kernel: [11265.697664]     .context       = ffff8801358c5bb0
Jun 25 13:47:20 dev906 kernel: [11265.697664]     .actual_length = 0
Jun 25 13:47:20 dev906 kernel: [11265.697664]     .status        = -115
Jun 25 13:47:20 dev906 kernel: [11265.697664]     .queue         = {.next =           (null), .prev =           (null)}
Jun 25 13:47:20 dev906 kernel: [11265.697664]     .state         =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.697664]   }
Jun 25 13:47:20 dev906 kernel: [11265.697697]   .xfer = ffff8801358c5c18 struct spi_transfer {
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .tx_buf        = ffff8800aeb08000
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .rx_buf        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .len           = 4096
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .tx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .rx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .cs_change     = 0
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .bits_per_word = 8
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .delay_usecs   = 0
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .speed_hz      = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.697697]     .transfer_list = {.next = ffff8801358c5c60, .prev = ffff8801358c5c60}
Jun 25 13:47:20 dev906 kernel: [11265.697697]   }
Jun 25 13:47:20 dev906 kernel: [11265.697713]   .pos             = 0
Jun 25 13:47:20 dev906 kernel: [11265.697713]   .pending_unacked = 60
Jun 25 13:47:20 dev906 kernel: [11265.697713]   .pending_bytes   = 60
Jun 25 13:47:20 dev906 kernel: [11265.697713]   .busy_count      = 0
Jun 25 13:47:20 dev906 kernel: [11265.697713]   .spi_in_flight   = 1
Jun 25 13:47:20 dev906 kernel: [11265.697721]   .ctl_cmd         = (null)
Jun 25 13:47:20 dev906 kernel: [11265.697723] }
Jun 25 13:47:20 dev906 kernel: [11265.697728] usb 2-1.3: submit_urbs: ----------SUBMITTING----------
Jun 25 13:47:20 dev906 kernel: [11265.697733] URB out: 00000000: 42 3c 00 00 19 65 19 46 21 65 21 46 21 65 21 66  B<...e.F!e!F!e!f
Jun 25 13:47:20 dev906 kernel: [11265.697737] URB out: 00000010: 21 85 21 86 29 a6 29 a6 21 c6 21 c7 22 05 21 e6  !.!.).).!.!.".!.
Jun 25 13:47:20 dev906 kernel: [11265.697741] URB out: 00000020: 29 e5 29 e6 22 05 22 06 2a 26 2a 27 32 26 2a 26  ).).".".*&*'2&*&
Jun 25 13:47:20 dev906 kernel: [11265.697745] URB out: 00000030: 32 25 2a 26 22 a6 1a 86 22 a5 22 86 2a 85 2a 85  2%*&"...".".*.*.
Jun 25 13:47:20 dev906 kernel: [11265.697750] usb 2-1.3: submit_urb: in
Jun 25 13:47:20 dev906 kernel: [11265.697757] usb 2-1.3: submit_urb: out
Jun 25 13:47:20 dev906 kernel: [11265.697763] usb 2-1.3: process_commands: exit_unlock
Jun 25 13:47:20 dev906 kernel: [11265.698383] usb 2-1.3: complete_urb: out, state: 0x1 urb->status: 0e, lock_held: 0, kill: 0
Jun 25 13:47:20 dev906 kernel: [11265.699261] usb 2-1.3: complete_urb: in, state: 0x1 urb->status: 0e, lock_held: 0, kill: 0
Jun 25 13:47:20 dev906 kernel: [11265.699267] usb 2-1.3: complete_urb: -------------RESPONSE------------
Jun 25 13:47:20 dev906 kernel: [11265.699271] URB in: 00000000: 42 00 00 20 00 00 00 00 00 00 00 00 00 00 00 00  B.. ............
Jun 25 13:47:20 dev906 kernel: [11265.699273] URB in: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.699275] URB in: 00000020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.699277] URB in: 00000030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.699280] usb 2-1.3: spi_complete_urb: 
Jun 25 13:47:20 dev906 kernel: [11265.699283] usb 2-1.3: spi_complete_urb: pin 0
Jun 25 13:47:20 dev906 kernel: [11265.699286] usb 2-1.3: spi_complete_urb: cmd->pending_bytes: 60 @ 10000000Hz
Jun 25 13:47:20 dev906 kernel: [11265.699289] usb 2-1.3: spi_complete_urb: expected_time_usec: 6147 (2 jiffies)
Jun 25 13:47:20 dev906 kernel: [11265.699292] usb 2-1.3: complete_urb: --------FINAL COMMAND STATE--------
Jun 25 13:47:20 dev906 kernel: [11265.699294] cmd: ffff8800a2348a80 struct mcp2210_cmd_type_spi {
Jun 25 13:47:20 dev906 kernel: [11265.699303]   .head = ffff8800a2348a80 struct mcp2210_cmd {
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .dev            = ffff8800a22eb800
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .type           = ffffffffa0415ba0 (spi)
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .node           = ffff8800a2348a90 struct list_head {.next = dead000000100100, .prev = dead000000200200}
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .time_queued    = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .time_started   = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .delay_until    = 4297709218
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .status         = 0
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .mcp_status     = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .state          = 2 ()
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .can_retry      = 0
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .delayed        = 1
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .nonatomic      = 0
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .repeat_count   = 0
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .complete       = ffffffffa040de20
Jun 25 13:47:20 dev906 kernel: [11265.699303]     .context        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.699303]   }
Jun 25 13:47:20 dev906 kernel: [11265.699318]   .spi = ffff880135e21c00 struct spi_device {
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .dev
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .master           = ffff8800a22ea800
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .max_speed_hz     = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .chip_select      = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .mode             = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .bits_per_word    = 0x08
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .irq              = 0
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .controller_state =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .controller_data  =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.699318]     .modalias         = fb_ssd1351
Jun 25 13:47:20 dev906 kernel: [11265.699318]   }
Jun 25 13:47:20 dev906 kernel: [11265.699330]   .msg = ffff8801358c5c60 struct spi_message {
Jun 25 13:47:20 dev906 kernel: [11265.699330]     .transfers     = {.next = ffff8801358c5c50, .prev = ffff8801358c5c50}
Jun 25 13:47:20 dev906 kernel: [11265.699330]     .spi           = ffff880135e21c00
Jun 25 13:47:20 dev906 kernel: [11265.699330]     .is_dma_mapped = 0
Jun 25 13:47:20 dev906 kernel: [11265.699330]     .complete      = ffffffff81515d40
Jun 25 13:47:20 dev906 kernel: [11265.699330]     .context       = ffff8801358c5bb0
Jun 25 13:47:20 dev906 kernel: [11265.699330]     .actual_length = 0
Jun 25 13:47:20 dev906 kernel: [11265.699330]     .status        = -115
Jun 25 13:47:20 dev906 kernel: [11265.699330]     .queue         = {.next =           (null), .prev =           (null)}
Jun 25 13:47:20 dev906 kernel: [11265.699330]     .state         =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.699330]   }
Jun 25 13:47:20 dev906 kernel: [11265.699341]   .xfer = ffff8801358c5c18 struct spi_transfer {
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .tx_buf        = ffff8800aeb08000
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .rx_buf        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .len           = 4096
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .tx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .rx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .cs_change     = 0
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .bits_per_word = 8
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .delay_usecs   = 0
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .speed_hz      = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.699341]     .transfer_list = {.next = ffff8801358c5c60, .prev = ffff8801358c5c60}
Jun 25 13:47:20 dev906 kernel: [11265.699341]   }
Jun 25 13:47:20 dev906 kernel: [11265.699350]   .pos             = 0
Jun 25 13:47:20 dev906 kernel: [11265.699350]   .pending_unacked = 0
Jun 25 13:47:20 dev906 kernel: [11265.699350]   .pending_bytes   = 60
Jun 25 13:47:20 dev906 kernel: [11265.699350]   .busy_count      = 0
Jun 25 13:47:20 dev906 kernel: [11265.699350]   .spi_in_flight   = 1
Jun 25 13:47:20 dev906 kernel: [11265.699354]   .ctl_cmd         = (null)
Jun 25 13:47:20 dev906 kernel: [11265.699356] }
Jun 25 13:47:20 dev906 kernel: [11265.699358] usb 2-1.3: process_commands: 
Jun 25 13:47:20 dev906 kernel: [11265.699361] usb 2-1.3: process_commands: running command ffff8800a2348a80 again (repeat_count = 1)
Jun 25 13:47:20 dev906 kernel: [11265.699364] usb 2-1.3: process_commands: delaying (atomic) execution for aprx. 8ms
Jun 25 13:47:20 dev906 kernel: [11265.699368] usb 2-1.3: process_commands: exit_unlock
Jun 25 13:47:20 dev906 kernel: [11265.704937] usb 2-1.3: timer_callback: 
Jun 25 13:47:20 dev906 kernel: [11265.704948] usb 2-1.3: process_commands: 
Jun 25 13:47:20 dev906 kernel: [11265.704954] usb 2-1.3: process_commands: running command ffff8800a2348a80 again (repeat_count = 1)
Jun 25 13:47:20 dev906 kernel: [11265.704964] usb 2-1.3: submit_urbs: 
Jun 25 13:47:20 dev906 kernel: [11265.704968] usb 2-1.3: spi_submit_prepare: pin 0
Jun 25 13:47:20 dev906 kernel: [11265.704973] usb 2-1.3: spi_submit_prepare: sending 4 bytes
Jun 25 13:47:20 dev906 kernel: [11265.704978] usb 2-1.3: spi_submit_prepare: len: 4, cmd->pending_bytes: 64
Jun 25 13:47:20 dev906 kernel: [11265.704982] submit_urbs: cmd = ffff8800a2348a80 struct mcp2210_cmd_type_spi {
Jun 25 13:47:20 dev906 kernel: [11265.704996]   .head = ffff8800a2348a80 struct mcp2210_cmd {
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .dev            = ffff8800a22eb800
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .type           = ffffffffa0415ba0 (spi)
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .node           = ffff8800a2348a90 struct list_head {.next = dead000000100100, .prev = dead000000200200}
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .time_queued    = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .time_started   = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .delay_until    = 4297709218
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .status         = 0
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .mcp_status     = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .state          = 0 ()
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .can_retry      = 0
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .delayed        = 0
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .nonatomic      = 0
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .repeat_count   = 1
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .complete       = ffffffffa040de20
Jun 25 13:47:20 dev906 kernel: [11265.704996]     .context        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.704996]   }
Jun 25 13:47:20 dev906 kernel: [11265.705028]   .spi = ffff880135e21c00 struct spi_device {
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .dev
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .master           = ffff8800a22ea800
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .max_speed_hz     = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .chip_select      = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .mode             = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .bits_per_word    = 0x08
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .irq              = 0
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .controller_state =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .controller_data  =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.705028]     .modalias         = fb_ssd1351
Jun 25 13:47:20 dev906 kernel: [11265.705028]   }
Jun 25 13:47:20 dev906 kernel: [11265.705087]   .msg = ffff8801358c5c60 struct spi_message {
Jun 25 13:47:20 dev906 kernel: [11265.705087]     .transfers     = {.next = ffff8801358c5c50, .prev = ffff8801358c5c50}
Jun 25 13:47:20 dev906 kernel: [11265.705087]     .spi           = ffff880135e21c00
Jun 25 13:47:20 dev906 kernel: [11265.705087]     .is_dma_mapped = 0
Jun 25 13:47:20 dev906 kernel: [11265.705087]     .complete      = ffffffff81515d40
Jun 25 13:47:20 dev906 kernel: [11265.705087]     .context       = ffff8801358c5bb0
Jun 25 13:47:20 dev906 kernel: [11265.705087]     .actual_length = 0
Jun 25 13:47:20 dev906 kernel: [11265.705087]     .status        = -115
Jun 25 13:47:20 dev906 kernel: [11265.705087]     .queue         = {.next =           (null), .prev =           (null)}
Jun 25 13:47:20 dev906 kernel: [11265.705087]     .state         =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.705087]   }
Jun 25 13:47:20 dev906 kernel: [11265.705106]   .xfer = ffff8801358c5c18 struct spi_transfer {
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .tx_buf        = ffff8800aeb08000
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .rx_buf        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .len           = 4096
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .tx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .rx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .cs_change     = 0
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .bits_per_word = 8
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .delay_usecs   = 0
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .speed_hz      = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.705106]     .transfer_list = {.next = ffff8801358c5c60, .prev = ffff8801358c5c60}
Jun 25 13:47:20 dev906 kernel: [11265.705106]   }
Jun 25 13:47:20 dev906 kernel: [11265.705123]   .pos             = 0
Jun 25 13:47:20 dev906 kernel: [11265.705123]   .pending_unacked = 4
Jun 25 13:47:20 dev906 kernel: [11265.705123]   .pending_bytes   = 64
Jun 25 13:47:20 dev906 kernel: [11265.705123]   .busy_count      = 0
Jun 25 13:47:20 dev906 kernel: [11265.705123]   .spi_in_flight   = 1
Jun 25 13:47:20 dev906 kernel: [11265.705130]   .ctl_cmd         = (null)
Jun 25 13:47:20 dev906 kernel: [11265.705133] }
Jun 25 13:47:20 dev906 kernel: [11265.705138] usb 2-1.3: submit_urbs: ----------SUBMITTING----------
Jun 25 13:47:20 dev906 kernel: [11265.705143] URB out: 00000000: 42 04 00 00 2a c5 2a c5 00 00 00 00 00 00 00 00  B...*.*.........
Jun 25 13:47:20 dev906 kernel: [11265.705147] URB out: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.705150] URB out: 00000020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.705154] URB out: 00000030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.705158] usb 2-1.3: submit_urb: in
Jun 25 13:47:20 dev906 kernel: [11265.705166] usb 2-1.3: submit_urb: out
Jun 25 13:47:20 dev906 kernel: [11265.705185] usb 2-1.3: process_commands: exit_unlock
Jun 25 13:47:20 dev906 kernel: [11265.707385] usb 2-1.3: complete_urb: out, state: 0x1 urb->status: 0e, lock_held: 0, kill: 0
Jun 25 13:47:20 dev906 kernel: [11265.708260] usb 2-1.3: complete_urb: in, state: 0x1 urb->status: 0e, lock_held: 0, kill: 0
Jun 25 13:47:20 dev906 kernel: [11265.708265] usb 2-1.3: complete_urb: -------------RESPONSE------------
Jun 25 13:47:20 dev906 kernel: [11265.708269] URB in: 00000000: 42 00 3c 30 00 00 00 00 00 00 00 00 00 00 00 00  B.<0............
Jun 25 13:47:20 dev906 kernel: [11265.708272] URB in: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.708274] URB in: 00000020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.708276] URB in: 00000030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.708279] usb 2-1.3: spi_complete_urb: 
Jun 25 13:47:20 dev906 kernel: [11265.708282] usb 2-1.3: spi_complete_urb: pin 0
Jun 25 13:47:20 dev906 kernel: [11265.708285] usb 2-1.3: spi_complete_urb: expected_time_usec: 0 (0 jiffies)
Jun 25 13:47:20 dev906 kernel: [11265.708287] usb 2-1.3: complete_urb: --------FINAL COMMAND STATE--------
Jun 25 13:47:20 dev906 kernel: [11265.708290] cmd: ffff8800a2348a80 struct mcp2210_cmd_type_spi {
Jun 25 13:47:20 dev906 kernel: [11265.708298]   .head = ffff8800a2348a80 struct mcp2210_cmd {
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .dev            = ffff8800a22eb800
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .type           = ffffffffa0415ba0 (spi)
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .node           = ffff8800a2348a90 struct list_head {.next = dead000000100100, .prev = dead000000200200}
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .time_queued    = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .time_started   = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .delay_until    = 4297709218
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .status         = 0
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .mcp_status     = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .state          = 2 ()
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .can_retry      = 0
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .delayed        = 0
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .nonatomic      = 0
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .repeat_count   = 1
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .complete       = ffffffffa040de20
Jun 25 13:47:20 dev906 kernel: [11265.708298]     .context        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708298]   }
Jun 25 13:47:20 dev906 kernel: [11265.708313]   .spi = ffff880135e21c00 struct spi_device {
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .dev
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .master           = ffff8800a22ea800
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .max_speed_hz     = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .chip_select      = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .mode             = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .bits_per_word    = 0x08
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .irq              = 0
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .controller_state =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .controller_data  =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708313]     .modalias         = fb_ssd1351
Jun 25 13:47:20 dev906 kernel: [11265.708313]   }
Jun 25 13:47:20 dev906 kernel: [11265.708325]   .msg = ffff8801358c5c60 struct spi_message {
Jun 25 13:47:20 dev906 kernel: [11265.708325]     .transfers     = {.next = ffff8801358c5c50, .prev = ffff8801358c5c50}
Jun 25 13:47:20 dev906 kernel: [11265.708325]     .spi           = ffff880135e21c00
Jun 25 13:47:20 dev906 kernel: [11265.708325]     .is_dma_mapped = 0
Jun 25 13:47:20 dev906 kernel: [11265.708325]     .complete      = ffffffff81515d40
Jun 25 13:47:20 dev906 kernel: [11265.708325]     .context       = ffff8801358c5bb0
Jun 25 13:47:20 dev906 kernel: [11265.708325]     .actual_length = 60
Jun 25 13:47:20 dev906 kernel: [11265.708325]     .status        = -115
Jun 25 13:47:20 dev906 kernel: [11265.708325]     .queue         = {.next =           (null), .prev =           (null)}
Jun 25 13:47:20 dev906 kernel: [11265.708325]     .state         =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708325]   }
Jun 25 13:47:20 dev906 kernel: [11265.708336]   .xfer = ffff8801358c5c18 struct spi_transfer {
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .tx_buf        = ffff8800aeb08000
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .rx_buf        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .len           = 4096
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .tx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .rx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .cs_change     = 0
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .bits_per_word = 8
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .delay_usecs   = 0
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .speed_hz      = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.708336]     .transfer_list = {.next = ffff8801358c5c60, .prev = ffff8801358c5c60}
Jun 25 13:47:20 dev906 kernel: [11265.708336]   }
Jun 25 13:47:20 dev906 kernel: [11265.708346]   .pos             = 60
Jun 25 13:47:20 dev906 kernel: [11265.708346]   .pending_unacked = 0
Jun 25 13:47:20 dev906 kernel: [11265.708346]   .pending_bytes   = 4
Jun 25 13:47:20 dev906 kernel: [11265.708346]   .busy_count      = 0
Jun 25 13:47:20 dev906 kernel: [11265.708346]   .spi_in_flight   = 1
Jun 25 13:47:20 dev906 kernel: [11265.708350]   .ctl_cmd         = (null)
Jun 25 13:47:20 dev906 kernel: [11265.708351] }
Jun 25 13:47:20 dev906 kernel: [11265.708354] usb 2-1.3: process_commands: 
Jun 25 13:47:20 dev906 kernel: [11265.708357] usb 2-1.3: process_commands: running command ffff8800a2348a80 again (repeat_count = 2)
Jun 25 13:47:20 dev906 kernel: [11265.708359] usb 2-1.3: submit_urbs: 
Jun 25 13:47:20 dev906 kernel: [11265.708362] usb 2-1.3: spi_submit_prepare: pin 0
Jun 25 13:47:20 dev906 kernel: [11265.708365] usb 2-1.3: spi_submit_prepare: sending 60 bytes
Jun 25 13:47:20 dev906 kernel: [11265.708368] usb 2-1.3: spi_submit_prepare: len: 60, cmd->pending_bytes: 64
Jun 25 13:47:20 dev906 kernel: [11265.708370] submit_urbs: cmd = ffff8800a2348a80 struct mcp2210_cmd_type_spi {
Jun 25 13:47:20 dev906 kernel: [11265.708378]   .head = ffff8800a2348a80 struct mcp2210_cmd {
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .dev            = ffff8800a22eb800
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .type           = ffffffffa0415ba0 (spi)
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .node           = ffff8800a2348a90 struct list_head {.next = dead000000100100, .prev = dead000000200200}
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .time_queued    = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .time_started   = 4297709216
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .delay_until    = 4297709218
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .status         = 0
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .mcp_status     = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .state          = 0 ()
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .can_retry      = 0
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .delayed        = 0
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .nonatomic      = 0
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .repeat_count   = 2
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .complete       = ffffffffa040de20
Jun 25 13:47:20 dev906 kernel: [11265.708378]     .context        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708378]   }
Jun 25 13:47:20 dev906 kernel: [11265.708392]   .spi = ffff880135e21c00 struct spi_device {
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .dev
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .master           = ffff8800a22ea800
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .max_speed_hz     = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .chip_select      = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .mode             = 0x00
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .bits_per_word    = 0x08
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .irq              = 0
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .controller_state =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .controller_data  =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708392]     .modalias         = fb_ssd1351
Jun 25 13:47:20 dev906 kernel: [11265.708392]   }
Jun 25 13:47:20 dev906 kernel: [11265.708403]   .msg = ffff8801358c5c60 struct spi_message {
Jun 25 13:47:20 dev906 kernel: [11265.708403]     .transfers     = {.next = ffff8801358c5c50, .prev = ffff8801358c5c50}
Jun 25 13:47:20 dev906 kernel: [11265.708403]     .spi           = ffff880135e21c00
Jun 25 13:47:20 dev906 kernel: [11265.708403]     .is_dma_mapped = 0
Jun 25 13:47:20 dev906 kernel: [11265.708403]     .complete      = ffffffff81515d40
Jun 25 13:47:20 dev906 kernel: [11265.708403]     .context       = ffff8801358c5bb0
Jun 25 13:47:20 dev906 kernel: [11265.708403]     .actual_length = 60
Jun 25 13:47:20 dev906 kernel: [11265.708403]     .status        = -115
Jun 25 13:47:20 dev906 kernel: [11265.708403]     .queue         = {.next =           (null), .prev =           (null)}
Jun 25 13:47:20 dev906 kernel: [11265.708403]     .state         =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708403]   }
Jun 25 13:47:20 dev906 kernel: [11265.708414]   .xfer = ffff8801358c5c18 struct spi_transfer {
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .tx_buf        = ffff8800aeb08000
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .rx_buf        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .len           = 4096
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .tx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .rx_dma        =           (null)
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .cs_change     = 0
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .bits_per_word = 8
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .delay_usecs   = 0
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .speed_hz      = 10000000
Jun 25 13:47:20 dev906 kernel: [11265.708414]     .transfer_list = {.next = ffff8801358c5c60, .prev = ffff8801358c5c60}
Jun 25 13:47:20 dev906 kernel: [11265.708414]   }
Jun 25 13:47:20 dev906 kernel: [11265.708423]   .pos             = 60
Jun 25 13:47:20 dev906 kernel: [11265.708423]   .pending_unacked = 60
Jun 25 13:47:20 dev906 kernel: [11265.708423]   .pending_bytes   = 64
Jun 25 13:47:20 dev906 kernel: [11265.708423]   .busy_count      = 0
Jun 25 13:47:20 dev906 kernel: [11265.708423]   .spi_in_flight   = 1
Jun 25 13:47:20 dev906 kernel: [11265.708427]   .ctl_cmd         = (null)
Jun 25 13:47:20 dev906 kernel: [11265.708428] }
Jun 25 13:47:20 dev906 kernel: [11265.708431] usb 2-1.3: submit_urbs: ----------SUBMITTING----------
Jun 25 13:47:20 dev906 kernel: [11265.708434] URB out: 00000000: 42 3c 00 00 22 e5 22 e6 2b 06 22 e6 3a 86 32 66  B<..".".+.".:.2f
Jun 25 13:47:20 dev906 kernel: [11265.708436] URB out: 00000010: 32 66 2a 66 2a a6 2a 86 32 86 32 86 32 a7 32 87  2f*f*.*.2.2.2.2.
Jun 25 13:47:20 dev906 kernel: [11265.708438] URB out: 00000020: 2a a5 2a a6 52 26 5a 67 29 e5 3a 88 2a 25 2a 26  *.*.R&Zg).:.*%*&
Jun 25 13:47:20 dev906 kernel: [11265.708441] URB out: 00000030: 58 c5 61 07 48 e6 38 85 30 e5 39 27 39 46 31 46  X.a.H.8.0.9'9F1F
Jun 25 13:47:20 dev906 kernel: [11265.708443] usb 2-1.3: submit_urb: in
Jun 25 13:47:20 dev906 kernel: [11265.708448] usb 2-1.3: submit_urb: out
Jun 25 13:47:20 dev906 kernel: [11265.708451] usb 2-1.3: process_commands: exit_unlock
Jun 25 13:47:20 dev906 kernel: [11265.709385] usb 2-1.3: complete_urb: out, state: 0x1 urb->status: 0e, lock_held: 0, kill: 0
Jun 25 13:47:20 dev906 kernel: [11265.710261] usb 2-1.3: complete_urb: in, state: 0x1 urb->status: 0e, lock_held: 0, kill: 0
Jun 25 13:47:20 dev906 kernel: [11265.710266] usb 2-1.3: complete_urb: -------------RESPONSE------------
Jun 25 13:47:20 dev906 kernel: [11265.710270] URB in: 00000000: 42 00 04 30 00 00 00 00 00 00 00 00 00 00 00 00  B..0............
Jun 25 13:47:20 dev906 kernel: [11265.710272] URB in: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Jun 25 13:47:20 dev906 kernel: [11265.710274] URB in: 00000020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
daniel-santos commented 10 years ago

Well first off, your contributions are most welcomed! I haven't played with this in the last few months and there are a lot of issues I've left unresolved. However, you're delving into one of the most important and also tricky areas.

So I'm first presuming that the performance stats you are talking about are with debugging turned off in the config (i.e., the out-of-tree-autoconf.h file). If not, just comment out CONFIG_MCP2210_DEBUG and CONFIG_MCP2210_DEBUG_VERBOSE and we're done here. Either way, I know for certain that performance is not yet optimal, although the framework is in place and being used (tuning of this would be in mcp2210-spi.c between in spi_complete_urb where we set the variable expected_time_usec). Also of note is the module parameter pending_bytes_wait_threshold which appears to be insufficiently documented. When the mcp2210's buffer has at least this many bytes in it, then the driver will delay before communicating again -- the default value is 45. Also, this value is ignored unless the rather stupidly named config option CONFIG_MCP2210_DONT_SUCK_THE_CPU_DRY is enabled. However, it turns out that disabling that parameter may also slow transfers due to taking too much time from the mcp2210 its self.

But moving on to the chip, it turns out that the mcp2210 is just a pre-programmed PIC of some sort (somebody figured out exactly which one, I forget) in a different package. It has an internal 64 byte buffer, but can only rx/tx 60 bytes of data at a time. I forget off-hand if this is a limitation of HID interrupt URBs or just the interface (I'm thinking that it's because it's designed to be HID compatible). So at the USB level, each message is 64 bytes, but that includes a 4 byte header.

The tricky part is figuring out the optimal delay between sending it more data, because each time we communicate with the mcp2210 via USB, it cannot be talking to the SPI device. So what you're seeing is that we send 60 bytes (42 3c 00 00), the maximum that we can and then it tells us that the transfer was started (42 00 00 20) and that no data has been transmitted yet (of course).

So timing is pretty skewed here because outputting debug info greatly impacts throughput. However, at 11265.704937 you see "usb 2-1.3: timer_callback:" -- if this weren't being debugged, there would have been an appreciable delay between this line and the one right before it. Instead, it pretty much fired as soon as we re-enabled interrupts. So for struct mcp2210_cmd_type_spi, pending_unacked is the number of bytes we have sent to the chip and not received an ACK (the 42 xx xx xx that doesn't indicate an error) and pending_bytes is the number of bytes that we have sent and had ACKed, but that the chip has not yet told us it sent and given us the peripheral's response. Why exactly we only send 4 bytes on the next communication I can't precisely recall, either the chip will NAK them (due to insufficient buffer space) or I have made an error. :) So maybe that is one that you can experiment with. In fact, I'm starting to think that it's the former, because I believe that it does not have a separate read & write buffer, so if we sent 60 bytes, when we already knew that it has 60 bytes to process, then we know that it can only take 4 bytes -- definitely something to confirm and document (probably in the README.md).

Let me know what you find out please!

mweal-ed commented 10 years ago

Thanks for the feedback. I'm off in the right direction now. One thing I have noticed is the performance is minimally impacted by the debugging.

I will let you know how things go.

mweal-ed commented 10 years ago

jiffies = 4ms.....argh

daniel-santos commented 10 years ago

The time value of jiffies depends upon CONFIG_HZ (Processor type and features -> Timer frequency) and you probably have yours set to 250 HZ. The use of jiffies is far more efficient (in clock cycles) than other mechanisms, although you get a lower resolution.

I was at first surprised that you saw little difference in performance without debugging, but then I remembered that I did most of my development & testing on a Raspberry Pi, which is quite a bit slower than the typical x86_64 machine!

Along the lines of clock cycles consumed by the driver is the use of packed structs -- this actually bloats the code quite a bit and is on my todo list, but I doubt it's an issue here. My worry is that you may not be able to achieve any descent throughput with the driver in its current form. This is because we set timers and ask to be awaken at a specified time and the contract here is that the timer will trigger no sooner than the specified time, but may occur later. Also, you should verify that the time that we expect to wake up is sane and not screwed up. Unfortunately, I've never done high speed tests on this because my application only needs small data transfers.

daniel-santos commented 10 years ago

How is it coming along? I'm thinking that we need some profiling debug messages, so we can turn off verbose messages, but emit a few messages that just show wake up, take action and go back to sleep stuff to make sure that the actual work the driver is doing isn't taking too long for some reason (which I suspect isn't the case).

Of course, only having a 64 byte buffer makes it hard to get anything close to full speed out of it.

EDIT: For clarification, we don't actually ever explicitly "sleep", we just set either a timer (for something that can be done in atomic mode) or a delayed_work (for something that may need to sleep).

daniel-santos commented 10 years ago

AHH!! It looks like we shouldn't be worried about the pending_bytes at all! So basically, it has a two separate 64 byte buffers, one for rx and tx. I just ran a test after making this change:

diff --git a/mcp2210-spi.c b/mcp2210-spi.c
index 1acacbf..47deb57 100644
--- a/mcp2210-spi.c
+++ b/mcp2210-spi.c
@@ -611,12 +611,14 @@ static int spi_submit_prepare(struct mcp2210_cmd *cmd_head)
        if (cmd->pos + cmd->pending_bytes < cmd->xfer->len) {
                len = cmd->xfer->len - cmd->pos - cmd->pending_bytes;

+#if 0
                /* don't try to send more than the buffer will hold */
                if (len > MCP2210_BUFFER_SIZE - cmd->pending_bytes) {
                        len = MCP2210_BUFFER_SIZE - cmd->pending_bytes;
                        if (!len)
                                goto buffer_full;
                }
+#endif

                if (len > MCP2210_BUFFER_SIZE - 4)
                        len = MCP2210_BUFFER_SIZE - 4;
@@ -631,7 +633,7 @@ static int spi_submit_prepare(struct mcp2210_cmd *cmd_head)
                cmd->pending_unacked = len;
                cmd->pending_bytes  += len;
        } else {
-buffer_full:
+//buffer_full:
                len = 0;
                start = NULL;
        }

And I did not get a NAK (usually status 0xf8) from the chip, so we're doing it wrong. :( Of course, that alone can only give an increase of roughly 87% and we need more than that. So we can basically send 60 bytes each time we talk to it (I suppose unless we talk to it too soon).

mweal-ed commented 10 years ago

Sorry for the late reply, I've been away for a few days.

1) I came to the same conclusion/changes about pending_bytes, but it only gave be about a 50% improvement in performance instead of 87%... not sure why.. could be the resolution of the performance data (from 4 to 6 kB/s). Not really important at this point.

2) Connected a Beagle USB bus analyzer. Could see I was getting a NAK (No interrupt pending) on the PCI bus for each In message and an associated elay until it was tried again. Thought this might be due to the EP_IN be submited before the EP_OUT, so tried switching the order. No improvement.

3) I was finding various delays due delayed _processing. Disabled CONFIG_MCP2210_DONT_SUCK_THE_CPU_DRY. Did not help the performance.

4) All rescheduling is using jiffies. xxx_to_jiffes all round up, so we always had 4 ms delay when we rescheduled. This is a long time when for these kind of transfers. Forced all delays < 1 second to 0. Still no improvement in performance.

5) With all these changes, looked at the bus analyzer again. We are getting 3 responses with a 0xF8 – SPI Data Not Accepted status taking about 7-8ms.

6) Check with scope. Was getting 100us between byte transfers. Realized I had my_power_up_spi_settings.delay_between_bytes to 0, but not my_board_config.spi.delay_between_bytes. Fixed and re-tested. Performance is now 13kB/s. still seeing 40-50us between byte transfers. With a data transfer of of 50us per byte we could achieve a maximum of 20 kB/s or 160 kb/s. This is still a lot less than I need.

In short, I think although we could make some improvements to the driver performance, but the overall performance is limited by the mcp2210.

daniel-santos commented 9 years ago

Sorry for my late response as well!

Thanks for your help on this. I'm going to update the documentation to reflect these hardware limitations (I suspected that we wouldn't get anything close to their "advertised" data rates). Also, will be tweaking out this driver too.

bogdanul2003 commented 9 years ago

Hi,

Did you manage to measure the maximum SPI output speed using your driver ? At the moment I'm using emulated SPI over GPIO on a openwrt router and I can't get above 1 MHz. Can mcp2210 chip and your drive provide better speed ?

Thank you

mweal-ed commented 9 years ago

Been a few months since I looked at this, but I believe I figured the maximum possible speed to be 160KHz and that would need a lot of optimization. The 160KHz is a limitation of the hardware.

bogdanul2003 commented 9 years ago

Do you know if there is a way to increase the speed of a emulated SPI over gpio ?

mweal-ed commented 9 years ago

It might be possible, but it would mean writing your own kernel driver dedicated to your hardware and environment and heavily optimized. This would also bog down linux. You could look at some of the other usb-spi bridges. I know the of the SILABS CP2130 which can do to the higher data rates, but I could never get it to work right in my application. I believe FTDI offers one, but I do not know what data rates it could handle. You could also program your own USB to SPI on a dedicated mcu. I believe you would have to write your own kernel driver for any of these.

madeintheusb commented 8 years ago

Our device Nusbio (http://www.nusbio.net) can do between 10 and 20 Kb/s in SPI using any .NET languages. And The FTDI FT232H can do from 1 to 3 M byte/S. it is an USB 2.0 Highspeed.

See my blog post http://madeintheusb.blogspot.com/2016/02/usb-to-spi-for-net.html

daniel-santos commented 8 years ago

Now that I've finished the base features that I originally intended for this driver (I finally got interrupts working), I'm considering abstracting it into an mcp2210-specific portion and a generic USB-to-x library and implementing the same functionality for the FT2xxx series via MPSSE. So I've started the process of trying to figure this out -- plus we could get all of the other protocols as well.

If any of you guys are aware of any other work on this I would appreciate a link. :)

EDIT: I would actually be interested in hardware suggestions. Among the qualities I'm looking for are: