[sane-devel] UMAX Astra 2200sc: slow calibration

[Tony van der Hoff]

Hi,

I'm able to obtain a scan from my Astra 2200, but it is taking in excess of
30 minutes to do so, the vast majority of this time reading 64 lines of
shading data at 2 lines/minute.

I've modified the debug output to include time information, and the relevant
extract from the log is as follows:

14:52:13 [umax] scanner ready
14:52:13 [umax] driver is doing calibration
14:52:13 [umax] request sense call is disabled
14:52:13 [umax] scanner sends 64 lines with 15300 pixels and 2 bytes/pixel
14:52:13 [umax] calculating average value for 16 bit shading data (low byte
first)!
14:52:13 [umax] read_shading_data
14:52:13 [umax] umax_scsi_cmd: calling sanei_scsi_cmd
14:52:13 [sanei_scsi] sanei_scsi_cmd
14:52:13 [sanei_scsi] scsi_req_enter: entered 0x80b63c8
14:52:13 [sanei_scsi] sanei_scsi.issue: 0x80b63c8
dev_max(currently)=32 max_active_device=5 (origin 1)
 def_reserved_size=32768
 >>> device=sg3 scsi1 chan=0 id=5 lun=0   em=0 sg_tablesize=128 excl=1
   FD(1): timeout=120000ms bufflen=34304 (res)sgat=2 low_dma=0
   cmd_q=1 f_packid=0 k_orphan=0 closed=0
     rb>> act: id=17 blen=30600 t_o/elap=120000/13ms sgat=0 op=0x28
14:52:13 [sanei_scsi] scsi_req_enter: queue_used: 1, queue_max: 2
14:52:13 [sanei_scsi] sanei_scsi_req_wait: waiting for 0x80b63c8
14:52:13 [sanei_scsi] sanei_scsi.issue: 0x80b63c8
dev_max(currently)=32 max_active_device=5 (origin 1)
 def_reserved_size=32768
 >>> device=sg3 scsi1 chan=0 id=5 lun=0   em=0 sg_tablesize=128 excl=1
   FD(1): timeout=120000ms bufflen=34304 (res)sgat=2 low_dma=0
   cmd_q=1 f_packid=0 k_orphan=0 closed=0
     rb>> rcv: id=17 blen=30600 dur=60276ms sgat=0 op=0x28
14:53:13 [sanei_scsi] sanei_scsi_req_wait: read 64 bytes
14:53:13 [umax] 16 bit shading-line 1 read
14:53:13 [umax] read_shading_data
14:53:13 [umax] umax_scsi_cmd: calling sanei_scsi_cmd
14:53:13 [sanei_scsi] sanei_scsi_cmd
14:53:13 [sanei_scsi] scsi_req_enter: entered 0x80b63c8
14:53:13 [sanei_scsi] sanei_scsi.issue: 0x80b63c8
dev_max(currently)=32 max_active_device=5 (origin 1)
 def_reserved_size=32768
 >>> device=sg3 scsi1 chan=0 id=5 lun=0   em=0 sg_tablesize=128 excl=1
   FD(1): timeout=120000ms bufflen=34304 (res)sgat=2 low_dma=0
   cmd_q=1 f_packid=0 k_orphan=0 closed=0
     rb>> act: id=18 blen=30600 t_o/elap=120000/14ms sgat=0 op=0x28
14:53:13 [sanei_scsi] scsi_req_enter: queue_used: 1, queue_max: 2
14:53:13 [sanei_scsi] sanei_scsi_req_wait: waiting for 0x80b63c8
14:53:13 [sanei_scsi] sanei_scsi.issue: 0x80b63c8
dev_max(currently)=32 max_active_device=5 (origin 1)
 def_reserved_size=32768
 >>> device=sg3 scsi1 chan=0 id=5 lun=0   em=0 sg_tablesize=128 excl=1
   FD(1): timeout=120000ms bufflen=34304 (res)sgat=2 low_dma=0
   cmd_q=1 f_packid=0 k_orphan=0 closed=0
     rb>> rcv: id=18 blen=30600 dur=24ms sgat=0 op=0x28
14:53:13 [sanei_scsi] sanei_scsi_req_wait: read 64 bytes
14:53:13 [umax] 16 bit shading-line 2 read
14:53:13 [umax] read_shading_data
14:53:13 [umax] umax_scsi_cmd: calling sanei_scsi_cmd
14:53:13 [sanei_scsi] sanei_scsi_cmd
14:53:13 [sanei_scsi] scsi_req_enter: entered 0x80b63c8
14:53:13 [sanei_scsi] sanei_scsi.issue: 0x80b63c8
dev_max(currently)=32 max_active_device=5 (origin 1)
 def_reserved_size=32768
 >>> device=sg3 scsi1 chan=0 id=5 lun=0   em=0 sg_tablesize=128 excl=1
   FD(1): timeout=120000ms bufflen=34304 (res)sgat=2 low_dma=0
   cmd_q=1 f_packid=0 k_orphan=0 closed=0
     rb>> act: id=19 blen=30600 t_o/elap=120000/12ms sgat=0 op=0x28
14:53:13 [sanei_scsi] scsi_req_enter: queue_used: 1, queue_max: 2
14:53:13 [sanei_scsi] sanei_scsi_req_wait: waiting for 0x80b63c8
14:53:13 [sanei_scsi] sanei_scsi.issue: 0x80b63c8

and so on, until

15:24:23 [sanei_scsi] sanei_scsi_req_wait: read 64 bytes
15:24:23 [umax] 16 bit shading-line 63 read
15:24:23 [umax] read_shading_data
15:24:23 [umax] umax_scsi_cmd: calling sanei_scsi_cmd
15:24:23 [sanei_scsi] sanei_scsi_cmd
15:24:23 [sanei_scsi] scsi_req_enter: entered 0x80b63c8
15:24:23 [sanei_scsi] sanei_scsi.issue: 0x80b63c8
dev_max(currently)=32 max_active_device=5 (origin 1)
 def_reserved_size=32768
 >>> device=sg3 scsi1 chan=0 id=5 lun=0   em=0 sg_tablesize=128 excl=1
   FD(1): timeout=120000ms bufflen=34304 (res)sgat=2 low_dma=0
   cmd_q=1 f_packid=0 k_orphan=0 closed=0
     rb>> act: id=80 blen=30600 t_o/elap=120000/13ms sgat=0 op=0x28
15:24:23 [sanei_scsi] scsi_req_enter: queue_used: 1, queue_max: 2
15:24:23 [sanei_scsi] sanei_scsi_req_wait: waiting for 0x80b63c8
15:24:23 [sanei_scsi] sanei_scsi.issue: 0x80b63c8
dev_max(currently)=32 max_active_device=5 (origin 1)
 def_reserved_size=32768
 >>> device=sg3 scsi1 chan=0 id=5 lun=0   em=0 sg_tablesize=128 excl=1
   FD(1): timeout=120000ms bufflen=34304 (res)sgat=2 low_dma=0
   cmd_q=1 f_packid=0 k_orphan=0 closed=0
     rb>> rcv: id=80 blen=30600 dur=23ms sgat=0 op=0x28
15:24:23 [sanei_scsi] sanei_scsi_req_wait: read 64 bytes
15:24:23 [umax] 16 bit shading-line 64 read
15:24:23 [umax] send_shading_data

After that it rapidly performs the scan, and exits.

Despite my best efforts, I don't understand the driver at this level, so is
there anyone out there who can make some suggestions on my next step in
debugging this issue, please?

Is the fact that it's taking almost exactly 60 seclonds to read two lines of
data significant?

FWIW, I'm running linux kernel 2.6.8, and have similar results with 2.6.11

Cheers,

-- 
Tony van der Hoff         | mailto:tony at vanderhoff.org
Buckinghamshire, England