SCSI problems with SANE 1.0.5, Linux 2.4.x and double buffering

From: Henning Meier-Geinitz (henning@meier-geinitz.de)
Date: Sat Jul 07 2001 - 05:57:29 PDT

  • Next message: Henning Meier-Geinitz: "Re: What's the status of sanei-thread?"

    Hi,

    I got several reports of SCSI problems with Mustek scanners in the
    last days. I don't think that these are mustek-bugs. The bug reporters
    provided the following common facts:

    * Linux 2.4.x
    * a SCSI controller that has a queue depth of 1 (e.g. Adaptec 1520)
    * SuSe 7.x (may be coincidence)

    They tried to scan an image but they only get the first stripe of
    aprox. 64k that is repeated until the page is completely scanned. The
    scanner stops after this first stripe. Sometimes the system freezes
    completely, sometimes there is only an error message and sometimes no
    error is output at all.

    I tried to reproduce this bug but couldn't until I did the following:
    rename /usr/include/scsi/sg.h to something else. After recompile
    sanei_scsi.c seems to use the kernel headers from /usr/src/linux
    (which are the right ones for my current kernel 2.4.5). I'm using
    Debian 2.2.

    It doesn't happen if I use a SCSI controller with a queue depth of 2
    or more (e.g. Adaptec 2940) or if I disable double buffering in
    mustek.c. Double buffering means, that the backend sends two read
    requests to the scanner before waiting for the first one. So maybe
    this is a bug in queuing the commands sanei_scsi.c? It works if I use
    a 2.2 kernel.

    Some parts of the debug log ans questions about it (color preview with
    a Paragon 1200SP). Questions/comments are marked with "---". The full
    logs are available on request.:

    [mustek] SANE mustek backend version 1.0 build 107 from sane-backends-1.0.5
    [...]
    [sanei_scsi] sanei_scsi_open: sanei_scsi_max_request_size=131072 bytes
    [sanei_scsi] sanei_scsi_open: SG driver version: 30117
    [sanei_scsi] sanei_scsi_open_extended: using 8192 bytes as SCSI buffer
    [sanei_scsi] trying to enable low level command queueing
    [sanei_scsi] sanei_scsi_open: Host adapter queue depth: 1
    [sanei_scsi] sanei_scsi_open: SG driver can change buffer size at run time
    [sanei_scsi] sanei_scsi_open: using new SG header structure
    --- The last line isn't printed if I use /usr/include/scsi/sg.h
    [...]
    [mustek] attach: sending INQUIRY
    [sanei_scsi] scsi_req_enter: entered 0x80f6d88
    [sanei_scsi] sanei_scsi.issue: 0x80f6d88
    dev_max(currently)=7 max_active_device=1 (origin 1)
     scsi_dma_free_sectors=48 sg_pool_secs_aval=320 def_reserved_size=32768
    >>> device=sg0 scsi0 chan=0 id=6 lun=0 em=0 sg_tablesize=255 excl=1
       FD(1): timeout=600000ms bufflen=8192 (res)sgat=0 low_dma=0
       cmd_q=1 f_packid=0 k_orphan=0 closed=0
         rb>> rcv: id=0 blen=96 dur=10ms sgat=0 op=0x12
    --- Where does this come from? I can't find it in sanei_scsci.c.
    [...]
    [mustek] sane_start
    [...]
    [mustek] reader_process: buffer 1: entering read request for 64470 bytes (buffer 1)
    [...]
    [mustek] reader_process: buffer 1: entered (line 35 of 995, buffer 1)
    [mustek] reader_process: buffer 2: entering read request for 64470 bytes (buffer 2)
    [...]
    [sanei_scsi] scsi_req_enter: entered 0x81d4150
    [sanei_scsi] sanei_scsi.issue: 0x81d4150
    [sanei_scsi] scsi_req_enter: queue_used: 1, queue_max: 1
    [mustek] reader_process: buffer 2: entered (line 70 of 995, buffer 2)
    [mustek] reader_process: buffer 1: waiting for request to be ready
    [sanei_scsi] sanei_scsi_req_wait: waiting for 0x81b2d58
    [sanei_scsi] sanei_scsi.issue: 0x81b2d58
    dev_max(currently)=7 max_active_device=1 (origin 1)
     scsi_dma_free_sectors=48 sg_pool_secs_aval=320 def_reserved_size=32768
    >>> device=sg0 scsi0 chan=0 id=6 lun=0 em=0 sg_tablesize=255 excl=1
       FD(1): timeout=600000ms bufflen=131072 (res)sgat=4 low_dma=0
       cmd_q=1 f_packid=0 k_orphan=0 closed=0
         rb>> rcv: id=14 blen=64470 dur=2690ms sgat=2 op=0x08
    [sanei_scsi] sanei_scsi.issue: 0x81d4150
    dev_max(currently)=7 max_active_device=1 (origin 1)
     scsi_dma_free_sectors=48 sg_pool_secs_aval=320 def_reserved_size=32768
    >>> device=sg0 scsi0 chan=0 id=6 lun=0 em=0 sg_tablesize=255 excl=1
       FD(1): timeout=600000ms bufflen=131072 (res)sgat=4 low_dma=0
       cmd_q=1 f_packid=0 k_orphan=0 closed=0
         rb>> rcv: id=15 blen=64470 dur=0ms sgat=2 op=0x83
    [sanei_scsi] sanei_scsi_req_wait: read 64 bytes
    --- Why is this only 64 bytes (that's printed for every req_wait even
        if the buffer is much bigger)?
    [mustek] reader_process: buffer 1 is ready, wanted 64470, got 64470 bytes
    [mustek] reader_process: buffer 1: sending 64470 bytes to output_data
    [...]
    [mustek] reader_process: buffer 1: entering read request for 64470 bytes (buffer 3)
    [...]

    This goes on until the full page is scanned. No error occurs but the
    resulting image conatines the first buffer over and over again.

    From a bug-reporter I got a debug log that's a bit different:

    [...]
    [sanei_scsi] sanei_scsi.issue: 0x80bcef0
    dev_max(currently)=9 max_active_device=3 (origin 1)
     scsi_dma_free_sectors=144 sg_pool_secs_aval=320 def_reserved_size=32768
    >>> device=sg0 scsi0 chan=0 id=6 lun=0 em=0 sg_tablesize=255 excl=1
       FD(1): timeout=600000ms bufflen=131072 (res)sgat=4 low_dma=0
       cmd_q=1 f_packid=0 k_orphan=0 closed=0
         rb>> act: id=12 blen=44208 t_o/elap=600000/40ms sgat=2 op=0x53
    [sanei_scsi] sanei_scsi_req_wait: read 64 bytes
    [sanei_scsi] sanei_scsi_req_wait: SCSI command complained: Success
    [sanei_scsi] sense buffer: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
    [sanei_scsi] target status: 00 host status: 0007 driver status: 0000
    [mustek] sense_handler: got sense code 00 for fd 7 (arg = null)
    [...]
    [mustek] reader_process: buffer 1: waiting for request to be ready
    [sanei_scsi] sanei_scsi_req_wait: waiting for 0x80bcef0
    [sanei_scsi] sanei_scsi.issue: 0x80bcef0
    dev_max(currently)=9 max_active_device=3 (origin 1)
     scsi_dma_free_sectors=144 sg_pool_secs_aval=320 def_reserved_size=32768
    >>> device=sg0 scsi0 chan=0 id=6 lun=0 em=0 sg_tablesize=255 excl=1
       FD(1): timeout=600000ms bufflen=131072 (res)sgat=4 low_dma=0
       cmd_q=1 f_packid=0 k_orphan=0 closed=0
         rb>> rcv: id=12 blen=44208 dur=260ms sgat=2 op=0x53
    [sanei_scsi] sanei_scsi.issue: 0x80e3710
    dev_max(currently)=9 max_active_device=3 (origin 1)
     scsi_dma_free_sectors=144 sg_pool_secs_aval=320 def_reserved_size=32768
    >>> device=sg0 scsi0 chan=0 id=6 lun=0 em=0 sg_tablesize=255 excl=1
       FD(1): timeout=600000ms bufflen=131072 (res)sgat=4 low_dma=0
       cmd_q=1 f_packid=0 k_orphan=0 closed=0
         rb>> act: id=13 blen=44208 t_o/elap=600000/30ms sgat=2 op=0x53
    [sanei_scsi] sanei_scsi_req_wait: read 64 bytes
    [sanei_scsi] sanei_scsi_req_wait: SCSI command complained: Success
    [sanei_scsi] sense buffer: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
    [sanei_scsi] target status: 00 host status: 0001 driver status: 0000
    [mustek] reader_process: failed to read data, status: Device busy, buffer: 1
    [...]

    --- What's this funny error message?

    Any ideas?

    Bye,
      Henning

    --
    Source code, list archive, and docs: http://www.mostang.com/sane/
    To unsubscribe: echo unsubscribe sane-devel | mail majordomo@mostang.com
    



    This archive was generated by hypermail 2b29 : Sat Jul 07 2001 - 05:49:28 PDT