OK. After further investigations, here is what I found so far:
SANE_DEBUG_SANEI_USB=11 scanimage -v -v -v --format=tiff> test.tiff 2> usb-verbose-11.log gives no delay at all but I can hear the carriage hangs/stops few times (each time being a millisecond or so) during the scan. [SANE_DEBBUG_SANEI_USB=11] 2012-02-07 12:25:06 scanimage: read 26780688 bytes in total 2012-02-07 12:25:06 Closing device 2012-02-07 12:25:06 [sanei_usb] sanei_usb_write_bulk: trying to write 2 bytes 2012-02-07 12:25:06 [sanei_usb] 0000: 1E 93 ................ 2012-02-07 12:25:06 [sanei_usb] sanei_usb_write_bulk: wanted 2 bytes, wrote 2 bytes 2012-02-07 12:25:06 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes 2012-02-07 12:25:06 [sanei_usb] 0000: 06 ................ 2012-02-07 12:25:06 [sanei_usb] sanei_usb_read_bulk: wanted 1 bytes, got 1 bytes 2012-02-07 12:25:06 [sanei_usb] sanei_usb_write_bulk: trying to write 1 bytes 2012-02-07 12:25:06 [sanei_usb] 0000: 00 ................ 2012-02-07 12:25:06 [sanei_usb] sanei_usb_write_bulk: wanted 1 bytes, wrote 1 bytes 2012-02-07 12:25:06 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes 2012-02-07 12:25:06 [sanei_usb] 0000: 06 ................ 2012-02-07 12:25:06 [sanei_usb] sanei_usb_read_bulk: wanted 1 bytes, got 1 bytes 2012-02-07 12:25:06 [sanei_usb] sanei_usb_close: closing device 0 2012-02-07 12:25:06 Calling sane_exit 2012-02-07 12:25:06 scanimage: finished SANE_DEBUG_SANEI_USB=10 scanimage -v -v -v --format=tiff> test.tiff 2> usb-verbose-10.log gives the bothering 3 minutes delay but the carriage movement during the scanning is perfectly smooth. [SANE_DEBUG_SANEI_USB=10] 2012-02-07 12:29:48 scanimage: read 26780688 bytes in total 2012-02-07 12:29:48 Closing device 2012-02-07 12:29:48 [sanei_usb] sanei_usb_write_bulk: trying to write 2 bytes 2012-02-07 12:29:48 [sanei_usb] sanei_usb_write_bulk: wanted 2 bytes, wrote 2 bytes 2012-02-07 12:29:48 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes 2012-02-07 12:30:18 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes 2012-02-07 12:30:48 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes 2012-02-07 12:31:18 [sanei_usb] sanei_usb_read_bulk: read failed: Resource temporarily unavailable 2012-02-07 12:31:18 [sanei_usb] sanei_usb_write_bulk: trying to write 1 bytes 2012-02-07 12:31:18 [sanei_usb] sanei_usb_write_bulk: wanted 1 bytes, wrote 1 bytes 2012-02-07 12:31:18 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes 2012-02-07 12:31:48 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes 2012-02-07 12:32:18 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes 2012-02-07 12:32:48 [sanei_usb] sanei_usb_read_bulk: read failed: Resource temporarily unavailable 2012-02-07 12:32:48 [sanei_usb] sanei_usb_close: closing device 0 2012-02-07 12:32:48 Calling sane_exit 2012-02-07 12:32:48 scanimage: finished I also noted that after a "3 minutes delay", I can't turn off the scanner (have to unplug it) so it seems something really bother it. As soon as I re-do a scan without the "3 minutes delay" (ie using SANE_DEBUG_SANEI_USB=11), then I can turn it off straight away without any problem. I continue my tests... Bests, Emmanuel Le 07/02/2012 00:55, Olaf Meeuwissen a ?crit : > "emmanuel.michel at wanadoo.fr"<emmanuel.michel at wanadoo.fr> writes: > >> Thanks Olaf for taking the time to help. >> >> OK, now it's even more obscure for me now... >> >> Tonight, I still have the same 3 minutes delay if I do for example: >> >> SANE_DEBUG_DLL=255 scanimage -v -v -v> test.pnm 2> dll-verbose.log >> >> or simply >> >> scanimage> test.pnm >> >> But, if I do: >> >> SANE_DEBUG_SANEI_USB=255 scanimage -v -v -v> test.pnm 2> usb-verbose.log >> >> I have absolutely no delay! > > Weird indeed. Anyone have any idea why this might happen? > > FYI, the epkowa backend uses sanei_usb_*_bulk() API to read and write > througout. The interpreter gets two callbacks that wrap this API. Do > note though that the backend uses a copy of sanei_usb.c from way back > (sane-backends 1.0.12, but we're updating as I write ;-). > >> [SANEI_USB] >> 2012-02-06 22:34:34 scanimage: read 26780688 bytes in total > > Looks like you did acquire an image so the backend is going through its > usual hoops. For a moment, I considered that scanimage might have just > exited rightaway without doing anything. > >> 2012-02-06 22:34:34 Closing device >> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_write_bulk: trying to write >> 2 bytes >> 2012-02-06 22:34:34 [sanei_usb] 0000: 1E 93 >> ................ >> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_write_bulk: wanted 2 bytes, >> wrote 2 bytes >> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes >> 2012-02-06 22:34:34 [sanei_usb] 0000: 06 ................ >> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_read_bulk: wanted 1 bytes, >> got 1 bytes >> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_write_bulk: trying to write >> 1 bytes >> 2012-02-06 22:34:34 [sanei_usb] 0000: 00 ................ >> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_write_bulk: wanted 1 bytes, >> wrote 1 bytes >> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes >> 2012-02-06 22:34:34 [sanei_usb] 0000: 06 ........$ >> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_read_bulk: wanted 1 bytes, >> got 1 bytes >> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_close: closing device 0 >> 2012-02-06 22:34:34 Calling sane_exit >> 2012-02-06 22:34:34 scanimage: finished >> >> Regarding your SANEI_USB_KEEP_USBLP suggestion, I see no difference in >> the log. Can you please confirm the use of this variable ? I presume >> you want me to use the following command: >> >> SANE_DEBUG_SANEI_USB=255 SANEI_USB_KEEP_USBLP=no scanimage -v -v -v> >> test.pnm 2> usb-verbose.log > > Yes, that usage is fine. The reason you see no difference is probably > because the usblp kernel module is blacklisted (by CUPS, IIRC). When > that's the case, the epkowa backend doesn't have to do anything special > to begin with. > > The backend detaches the usblp module before scanning and re-attaches > it when done. This is an ugly hack to get a number of all-in-ones to > behave again with 2.6.13 kernels or later. I thought that maybe that > re-attaching was causing the 3 minute wait. Guess not. > >> Le 06/02/2012 04:53, Olaf Meeuwissen a ?crit : >>> "emmanuel.michel at wanadoo.fr"<emmanuel.michel at wanadoo.fr> writes: >>> >>>> The setup: >>>> Scanner EPSON Prefection V200 >>>> OS Ubuntu Server 64 bits 10.04.3 >>>> >>>> libsane 1.0.20-13ubuntu2 >>>> sane-utils 1.0.20-13ubuntu2 >>>> iscan 2.28.1-3.ltdl7 >>>> iscan-data 1.14.0-1 >>>> iscan-plugin-gt-f670 2.1.2-1 >>>> >>>> The problem: >>>> Everytime I scan a document with scanimage I have to wait _exactly_ 3 >>>> minutes before it returns to the command line. Below are the end of >>>> the debug logs from dll and epkowa: >>>> >>>> [DLL] >>>> 2012-02-05 20:48:31 scanimage: read 26780688 bytes in total >>>> 2012-02-05 20:48:31 [dll] sane_cancel(handle=0x1088da0) >>>> 2012-02-05 20:48:31 Closing device >>>> 2012-02-05 20:48:31 [dll] sane_close(handle=0x1088da0) >>>> 2012-02-05 20:51:31 Calling sane_exit >>>> 2012-02-05 20:51:31 [dll] sane_exit: exiting >>>> 2012-02-05 20:51:31 [dll] sane_exit: calling backend `epkowa's exit >>>> function >>>> 2012-02-05 20:51:31 [dll] sane_exit: finished >>>> 2012-02-05 20:51:31 scanimage: finished >>>> >>>> [EPKOWA] >>>> 2012-02-05 20:58:42 scanimage: read 26780688 bytes in total >>>> 2012-02-05 20:58:42 epkowa.c:5955: [epkowa]{C} sane_epkowa_cancel >>>> 2012-02-05 20:58:42 device.c:536: [epkowa]{C} dev_unlock >>>> 2012-02-05 20:58:42 Closing device >>>> 2012-02-05 20:58:42 epkowa.c:2554: [epkowa]{C} sane_epkowa_close >>>> 2012-02-05 20:58:42 device.c:242: [epkowa]{C} dev_close (fd = 0) >>>> 2012-02-05 21:01:42 Calling sane_exit >>>> 2012-02-05 21:01:42 backend.c:251: [epkowa]{C} sane_epkowa_exit () >>>> 2012-02-05 21:01:42 dip-obj.c:152: [epkowa]{C} dip_exit (0x1fe46b0) >>>> 2012-02-05 21:01:42 cfg-obj.c:468: [epkowa]{C} cfg_has (0x1fdf630, 4) >>>> 2012-02-05 21:01:42 cfg-obj.c:468: [epkowa]{C} cfg_has (0x1fdf630, 3) >>>> 2012-02-05 21:01:42 cfg-obj.c:468: [epkowa]{C} cfg_has (0x1fdf630, 2) >>>> 2012-02-05 21:01:42 cfg-obj.c:468: [epkowa]{C} cfg_has (0x1fdf630, 1) >>>> 2012-02-05 21:01:42 cfg-obj.c:411: [epkowa]{C} cfg_exit (0x1fdf630) >>>> 2012-02-05 21:01:42 model-info.c:209: [epkowa]{C} model_info_cache_exit >>>> (0x1fdf$ >>>> 2012-02-05 21:01:42 scanimage: finished >>>> >>>> As you can see, I always have this 3 minutes delay just after >>>> sane_close. I would be glad if someone could help me to understand >>>> what this temporal hole is about. Thanks in advance. >>> >>> This is caused by one or more of: >>> - the interpreter taking its time to clean up and leave the device in a >>> consistent state >>> - the SANE USB layer taking its time to reattach the usblp module >>> >>> To identify the culprit could you please provide the relevant part of >>> the SANEI_USB log, with and without the SANEI_USB_KEEP_USBLP variable >>> set? This environment variable can be set to completely disable the >>> (iscan specific) usblp module tweaks in the backend. > > Sorry that this doesn't help,