Skip to contentSkip to conversation

2.6.19.1, sata_sil: sata dvd writer doesn't work

PATCH Harald Dunkel 5 participants 17 messages May 4, 2007 – Jun 19, 2007 9 messages not in the archive

Subsystems (2)
libata Uniform cdrom driver
lore
Share & tools
lore

Harald Dunkel

author
#5 lore raw
In reply to a message not in the archive

Hi folks,

Tejun Heo suggested to post my problem here.

If I enter a movie DVD into my drive (Samsung SH-S183A, SATA) and run xine dvd:/dev/scd0 immediately (while the drive's LED is still blinking), then there is some timeout problem. kern.log says:

May  4 19:10:17 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
May  4 19:10:17 pluto kernel: ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xa4 data 8 in
May  4 19:10:17 pluto kernel:          res 40/00:02:00:04:08/00:00:00:00:00/a0 Emask 0x4 (timeout)
May  4 19:10:17 pluto kernel: ata2: soft resetting port
May  4 19:10:24 pluto kernel: ata2: port is slow to respond, please be patient (Status 0xf8)
May  4 19:10:47 pluto kernel: ata2: port failed to respond (30 secs, Status 0xf8)
May  4 19:10:47 pluto kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  4 19:10:47 pluto kernel: ATA: abnormal status 0xF8 on port 0xffffc2000001a0c7
May  4 19:10:47 pluto last message repeated 5 times
May  4 19:11:17 pluto kernel: ata2.00: qc timeout (cmd 0xa1)
May  4 19:11:17 pluto kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
May  4 19:11:17 pluto kernel: ata2.00: revalidation failed (errno=-5)
May  4 19:11:17 pluto kernel: ata2: failed to recover some devices, retrying in 5 secs
May  4 19:11:22 pluto kernel: ata2: hard resetting port
May  4 19:11:23 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  4 19:11:23 pluto kernel: ata2.00: XXX: IDENTIFY
May  4 19:11:23 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 08: 0000 0000 2020 2020  2020 2020 2020 2020
May  4 19:11:23 pluto kernel: 10: 2020 2020 2020 2020  0000 0000 0000 5342
May  4 19:11:23 pluto kernel: 18: 3032 2020 2020 5453  5354 636f 7270 4344
May  4 19:11:23 pluto kernel: 20: 2f44 5644 5720 5348  2d53 3138 3341 2020
May  4 19:11:23 pluto kernel: 28: 2020 2020 2020 2020  2020 2020 2020 0000
May  4 19:11:23 pluto kernel: 30: 0000 0f00 0000 0200  0200 0006 0000 0000
May  4 19:11:23 pluto kernel: 38: 0000 0000 0000 0000  0000 0000 0000 0007
May  4 19:11:23 pluto kernel: 40: 0003 0078 0078 0078  0078 0000 0000 0000
May  4 19:11:23 pluto kernel: 48: 0000 0000 0000 0000  0602 0000 0068 0040
May  4 19:11:23 pluto kernel: 50: 0000 0000 0000 4000  4000 0000 0000 4000
May  4 19:11:23 pluto kernel: 58: 0407 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 60: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 68: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 70: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 78: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 80: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 88: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 90: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 98: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: a0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: a8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: b0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: b8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: c0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: c8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: d0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: d8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: e0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: e8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: f0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: f8: 0000 0000 0000 0000  0000 0000 0000 9ca5
May  4 19:11:23 pluto kernel: ata2.00: configured for UDMA/33
May  4 19:11:23 pluto kernel: ata2: EH complete

Its pretty much reproducible. For the example above the DVD played at the end, but sometimes the DVD drive dies, and I have to reboot.

If I enter a data DVD and try to mount it without waiting, then I get

% mount /cdrom
mount: /dev/scd0 already mounted or /cdrom busy
% mount /cdrom
%

There is no message in kern.log in this case. On the second try it succeeds, as shown above.

If I enter a data DVD without running anything, then it takes about 15 seconds till the LED goes off. Movie DVDs are a little bit faster: 12 secs. But I am sure this depends.

Any help would be highly appreciated. Please keep me on CC:; I haven't subscribed this ML.

Regards

Harri
==========================================================================

Quoted 40 lines · Tejun Heo
Quoted 18 lines · Harald Dunkel

Hi Tejun,

Quoted 3 lines · Tejun Heo

The timeout is normal. As the drive is still trying to recognize the dvd, it doesn't respond to commands in the time specified by xine or whatever.

I never saw this before with any other drive.

Quoted 5 lines

Interestingly, the drive reports illegal device type after such event. Can you please apply the attached patch and report the dmesg after such failure?

Here it is:

ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in

Quoted 8 lines
         res 40/00:02:00:0c:00/00:00:00:00:00/a0 Emask 0x4 (timeout)

ata2: soft resetting port
CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0) ata2.00: revalidation failed (errno=-22)
ata2.00: disabled
ata2: EH complete

Thanks.

Can you please apply the attached patch and report this problem to
[email protected] with the resulting dmesg? It seems your
drive reports incorrect IDENTIFY data (maybe due to unflushed FIFO) after such timeout event. I think the timeout itself is probably okay.
The drive might just take a tad bit longer than other drives (how long
do you have to wait?).

Thanks.

#19 lore raw
In reply to a message not in the archive
Quoted 67 lines · Tejun Heo
Quoted 41 lines · Daniel Beichl

I reverted to my initial patch and added a printk line to log the first command byte and
qc->nbytes for each command that has been reduced to pio and authenticated a dvd:

not Authenticated
ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
Request AGID [1]... AGID 3

Host sending challenge:  68 96 40 A8 F2 1A 66 ED A9 33
ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
ata2.00: Reduce cmd 0xa3 (nbytes=0) to pio
LU sent key1:  65 A0 60 C5 22
Drive Authentic - using varient 0
ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
LU sent challenge:  D8 D1 AA A6 45 A8 40 33 1C CB
Host sending key 2:  A7 90 93 04 B6
ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio

DVD is authenticated
Received Session Key: 7C A0 0F E9 E2
ata2.00: Reduce cmd 0xa3 (nbytes=0) to pio
not Authenticated
ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
Received Disc Key: 55 43 42 B3 C5 FB 6A 00 46 39
Authenticated
ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio

As you can see, every command had a qc->nbytes of zero, therefore your code would have allowed dma transfer as "(0 & 511) != 0" is false(0)
and returning 0 allows dma.

I wonder why these commands have a nbytes of zero, perhaps its the amount of data sectors transferred? I have searched
the libata documentation pdf and did a quick google search, but i didn't come up with anything useful.
So your suggestion would work if you say size is not aligned to ATA_SECT_SIZE or zero, i.e:

/* returning 0 allows dma everything else does not */ return ((qc->nbytes & (ATA_SECT_SIZE-1)) || (qc->nbytes == 0));

Quoted 7 lines

But why do you think this should be dependent on the qc->nbytes attribute as the authentification commands all have nbytes set to zero? Are you aware of some other issues with this sata controller?

It would be great to drill this down further, but i have no clue how to continue. If you have any suggestions please let me know.

Okay, I've been thinking about it for some time. I think I know what's going on now. Those authentication related commands are issued by invoking ioctls on the device node. The cdrom driver receives the ioctls and issues respective SCSI commands for it. All those DVD auth commands either transfer or receive data from the device and thus specifies certain data direction when they're issued. libata selects command protocol accordingly.

It's all good and dandy till now but the problem is that those commands can be issued with data length of zero! This is allowed by the SCSI MMC standard and used to probe whether the command succeeds or not before taking further actions. When this happens, libata chooses command protocol according to the data direction, but has to feed 0-length data to the DMA engine. It seems sata_sil dma engine barfs if that happens.
Can you please add the following code snippet at the head of atapi_xlat()?

Quoted 10 lines
	if (!nodata && !qc->nbytes) {
		printk("XXX forcing PIO for 0 length data cdb %02x\n",
			scmd->cmnd[0]);
		dump_stack();
		using_pio = 1;
	}

Also, do you mind cc'ing [email protected]?

Hi Tejun,

i inserted the code snippet you mentioned to atapi_xlat() in libata-scsi.c and the dvd authentication succeeds.

Please see the attached dmesg file for the generated stack dumps.

The question is whether this is the right place to fix it, as this seems to limit all drivers to pio if a zero data length command is transferred.
It would make more sense to me if the individual driver decides this by performing a similar check in the check_atapi_dma function implemented by the individual driver. I did this for the sata_sil driver in the attached patch.

Thanks for sharing your insight,

Daniel

.c: subsystem: 01297:a550 bound to 0000:00:05.0
ACPI: PCI Interrupt Link [LNK2] enabled at IRQ 11
PCI: setting IRQ 11 as level-triggered
ACPI: PCI Interrupt 0000:01:05.0[A] -> Link [LNK2] -> GSI 11 (level, low) -> IRQ 11
sym0: <875> rev 0x26 at pci 0000:01:05.0 irq 11
ACPI: PCI Interrupt Link [LUB2] enabled at IRQ 9
PCI: setting IRQ 9 as level-triggered
ACPI: PCI Interrupt 0000:00:02.2[C] -> Link [LUB2] -> GSI 9 (level, low) -> IRQ 9
PCI: Setting latency timer of device 0000:00:02.2 to 64
ehci_hcd 0000:00:02.2: EHCI Host Controller
ehci_hcd 0000:00:02.2: new USB bus registered, assigned bus number 1
ehci_hcd 0000:00:02.2: debug port 1
PCI: cache line size of 64 is not supported by device 0000:00:02.2
ehci_hcd 0000:00:02.2: irq 9, io mem 0xe8005000
ehci_hcd 0000:00:02.2: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
usb usb1: configuration #1 chosen from 1 choice
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 6 ports detected
sym0: Tekram NVRAM, ID 7, Fast-20, SE, parity checking
sym0: SCSI BUS has been reset.
scsi2 : sym-2.2.3
usb 1-2: new high speed USB device using ehci_hcd and address 3
usb 1-2: configuration #1 chosen from 1 choice
hub 1-2:1.0: USB hub found
hub 1-2:1.0: 4 ports detected
usb 1-3: new high speed USB device using ehci_hcd and address 4
usb 1-3: configuration #1 chosen from 1 choice
usb 1-2.1: new high speed USB device using ehci_hcd and address 5
usb 1-2.1: configuration #1 chosen from 1 choice
ACPI: PCI Interrupt Link [LUBA] enabled at IRQ 9
ACPI: PCI Interrupt 0000:00:02.0[A] -> Link [LUBA] -> GSI 9 (level, low) -> IRQ 9
PCI: Setting latency timer of device 0000:00:02.0 to 64
ohci_hcd 0000:00:02.0: OHCI Host Controller
ohci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2
ohci_hcd 0000:00:02.0: irq 9, io mem 0xe8003000
usb usb2: configuration #1 chosen from 1 choice
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 3 ports detected
ACPI: PCI Interrupt Link [LUBB] enabled at IRQ 9
ACPI: PCI Interrupt 0000:00:02.1[B] -> Link [LUBB] -> GSI 9 (level, low) -> IRQ 9
PCI: Setting latency timer of device 0000:00:02.1 to 64
ohci_hcd 0000:00:02.1: OHCI Host Controller
ohci_hcd 0000:00:02.1: new USB bus registered, assigned bus number 3
ohci_hcd 0000:00:02.1: irq 9, io mem 0xe8004000
Initializing USB Mass Storage driver...
ieee80211_crypt: registered algorithm 'NULL'
usb usb3: configuration #1 chosen from 1 choice
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 3 ports detected
ieee80211: 802.11 data/management/control stack, git-1.1.13
ieee80211: Copyright (C) 2004-2005 Intel Corporation <[email protected]>
scsi3 : SCSI emulation for USB Mass Storage devices
usb-storage: device found at 4
usb-storage: waiting for device to settle before scanning
i2c_adapter i2c-0: nForce2 SMBus adapter at 0x4c00
i2c_adapter i2c-1: nForce2 SMBus adapter at 0x4c40
ACPI: PCI Interrupt Link [LNK3] enabled at IRQ 3
PCI: setting IRQ 3 as level-triggered
ACPI: PCI Interrupt 0000:01:06.0[A] -> Link [LNK3] -> GSI 3 (level, low) -> IRQ 3
ohci1394: fw-host0: OHCI-1394 1.0 (PCI): IRQ=[3] MMIO=[e7002000-e70027ff] Max Packet=[2048] IR/IT contexts=[4/8]
ACPI: PCI Interrupt Link [LNK5] enabled at IRQ 14
PCI: setting IRQ 14 as level-triggered
ACPI: PCI Interrupt 0000:02:00.0[A] -> Link [LNK5] -> GSI 14 (level, low) -> IRQ 14
radeonfb: Found Intel x86 BIOS ROM Image
radeonfb: Retrieved PLL infos from BIOS
radeonfb: Reference=27.00 MHz (RefDiv=12) Memory=250.00 Mhz, System=200.00 MHz
radeonfb: PLL min 20000 max 40000
usb 2-1: new low speed USB device using ohci_hcd and address 2
usb 2-1: configuration #1 chosen from 1 choice
usbcore: registered new interface driver usb-storage
USB Mass Storage support registered.
radeonfb: Monitor 1 type DFP found
radeonfb: EDID probed
radeonfb: Monitor 2 type CRT found
radeonfb: EDID probed
Console: switching to colour frame buffer device 160x64
radeonfb (0000:02:00.0): ATI Radeon Ya
usb 1-2.1: reset high speed USB device using ehci_hcd and address 5
zd1211rw 1-2.1:1.0: firmware version 4725
zd1211rw 1-2.1:1.0: zd1211b chip 0586:340f v4810 high 00-13-49 AL2230_RF pa0 g---
zd1211rw 1-2.1:1.0: eth1
usbcore: registered new interface driver zd1211rw
input: Logitech USB Mouse as /class/input/input2
usbcore: registered new interface driver usbmouse
drivers/usb/input/usbmouse.c: v1.6:USB HID Boot Protocol mouse driver
usbcore: registered new interface driver hiddev
usbcore: registered new interface driver usbhid
drivers/usb/input/hid-core.c: v2.6:USB HID core driver
ieee1394: Host added: ID:BUS[0-00:1023] GUID[00301bb10000d279]
eth1394: eth1: IEEE-1394 IPv4 over 1394 Ethernet (fw-host0)
EXT3 FS on sda2, internal journal

usbcore: registered new interface driver usbkbd
drivers/usb/input/usbkbd.c: :USB HID Boot Protocol keyboard driver
powernow-k8: Found 1 AMD Athlon(tm) 64 Processor 3000+ processors (version 2.00.00)
powernow-k8:    0 : fid 0xc (2000 MHz), vid 0x2
powernow-k8:    1 : fid 0xa (1800 MHz), vid 0x6
powernow-k8:    2 : fid 0x0 (800 MHz), vid 0xa
it87: Found IT8712F chip at 0x290, revision 5
device-mapper: ioctl: 4.11.0-ioctl (2006-10-12) initialised: [email protected]

fuse init (API version 7.8)
kjournald starting. Commit interval 5 seconds
EXT3 FS on sda3, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
scsi 3:0:0:0: Direct-Access USB2.0 CardReader CF RW 0.0> PQ: 0 ANSI: 0
sd 3:0:0:0: Attached scsi removable disk sdb
sd 3:0:0:0: Attached scsi generic sg2 type 0
scsi 3:0:0:1: Direct-Access USB2.0 CardReader Combo 0.0> PQ: 0 ANSI: 0
sd 3:0:0:1: Attached scsi removable disk sdc
sd 3:0:0:1: Attached scsi generic sg3 type 0
usb-storage: device scan complete
eth0: no link during initialization.
ttyS1: LSR safety check engaged!
ttyS1: LSR safety check engaged!
eth0: no link during initialization.
SoftMAC: Open Authentication completed with 00:13:49:9a:e2:79
input: Power Button (FF) as /class/input/input3
ACPI: Power Button (FF) [PWRF]
input: Power Button (CM) as /class/input/input4
ACPI: Power Button (CM) [PWRB]
ACPI: Fan [FAN] (on)
ACPI: Thermal Zone [THRM] (40 C)
NET: Registered protocol family 10
lo: Disabled Privacy Extensions ADDRCONF(NETDEV_UP): eth0: link is not ready
ieee80211_crypt: registered algorithm 'TKIP'
Time: acpi_pm clocksource has been installed. Clocksource tsc unstable (delta = -259997568 ns) [drm] Initialized drm 1.1.0 20060810
[drm] Initialized radeon 1.25.0 20060524 on minor 0
agpgart: Found an AGP 3.0 compliant device at 0000:00:00.0.
agpgart: Putting AGP V3 device at 0000:00:00.0 into 4x mode
agpgart: Putting AGP V3 device at 0000:02:00.0 into 4x mode [drm] Setting GART location based on new memory map [drm] Loading R200 Microcode
[drm] writeback test succeeded in 1 usecs
wlan0: no IPv6 routers present
XXX forcing PIO for 0 length data cdb a4

 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862934>] dvd_do_auth+0x261/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c016ab9e>] link_path_walk+0xa9/0xb3
 [<c0161589>] get_unused_fd+0x4a/0xa9
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c016a961>] __link_path_walk+0xa66/0xbfa
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01bdfd2>] exact_lock+0x7/0xd
 [<c01c436f>] kobject_get+0xf/0x13
 [<f8845363>] sr_block_open+0x74/0x81 [sr_mod]
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c018186a>] bdget+0xe7/0xef
 [<c0149071>] find_get_page+0x18/0x38
 [<c014b33f>] filemap_nopage+0x18d/0x2ef
 [<c0181c6d>] blkdev_open+0x25/0x4d
 [<c0153ddc>] __handle_mm_fault+0x2cd/0x793
 [<c016181d>] do_filp_open+0x32/0x39
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862766>] dvd_do_auth+0x93/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0149071>] find_get_page+0x18/0x38
 [<c014b33f>] filemap_nopage+0x18d/0x2ef
 [<c0211893>] pty_write+0x2f/0x39
 [<c0153ddc>] __handle_mm_fault+0x2cd/0x793
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a3
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f88629b9>] dvd_do_auth+0x2e6/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f88627c8>] dvd_do_auth+0xf5/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862826>] dvd_do_auth+0x153/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a3
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862a1f>] dvd_do_auth+0x34c/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862934>] dvd_do_auth+0x261/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb ad
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0146ff6>] handle_IRQ_event+0x1a/0x3f
 [<c0107acc>] enable_8259A_irq+0xd/0x42
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0106382>] do_IRQ+0x5c/0x72
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8863939>] mmc_ioctl+0xdbe/0x11e5 [cdrom]
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f8852b92>] do_get_write_access+0x4b6/0x4e3 [jbd]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862934>] dvd_do_auth+0x261/0x4a8 [cdrom]
 [<f88949d2>] __ext3_journal_dirty_metadata+0x16/0x3a [ext3]
 [<f88896d1>] __ext3_get_inode_loc+0x115/0x2e3 [ext3]
 [<f8887405>] ext3_new_blocks+0x4b7/0x5bd [ext3]
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c017dad1>] __find_get_block+0x14c/0x156
 [<c017dafe>] __getblk+0x23/0x26c
 [<f8852b92>] do_get_write_access+0x4b6/0x4e3 [jbd]
 [<c017dad1>] __find_get_block+0x14c/0x156
 [<f88896d1>] __ext3_get_inode_loc+0x115/0x2e3 [ext3]
 [<f88949d2>] __ext3_journal_dirty_metadata+0x16/0x3a [ext3]
 [<f8852be0>] journal_get_write_access+0x21/0x26 [jbd]
 [<f8889556>] ext3_mark_iloc_dirty+0x26e/0x2d4 [ext3]
 [<f888992d>] ext3_mark_inode_dirty+0x20/0x27 [ext3]
 [<c0119df7>] __wake_up+0x32/0x43
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<c014a791>] generic_file_buffered_write+0x597/0x606
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c0124548>] current_fs_time+0x41/0x46
 [<c014ace5>] __generic_file_aio_write_nolock+0x4e5/0x55e
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c014adbc>] generic_file_aio_write+0x5e/0xb3
 [<f8888020>] ext3_file_write+0x24/0x8f [ext3]
 [<c016290a>] do_sync_write+0xc7/0x10a
 [<c016bae2>] open_namei+0x24c/0x552
 [<c01617dc>] nameidata_to_filp+0x24/0x33
 [<c0130b89>] autoremove_wake_function+0x0/0x35
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c0174aed>] mntput_no_expire+0x11/0x68
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
sata_sil.c +20 -1
@@ -43,10 +43,11 @@
 #include <linux/interrupt.h>
 #include <linux/device.h>
 #include <scsi/scsi_host.h>
+#include <scsi/scsi_cmnd.h>
 #include <linux/libata.h>
 
 #define DRV_NAME	"sata_sil"
-#define DRV_VERSION	"2.1"
+#define DRV_VERSION	"2.1a"
 
 enum {
 	SIL_MMIO_BAR		= 5,

@@ -121,6 +122,7 @@
 static irqreturn_t sil_interrupt(int irq, void *dev_instance);
 static void sil_freeze(struct ata_port *ap);
 static void sil_thaw(struct ata_port *ap);
+static int sil_check_atapi_dma(struct ata_queued_cmd *qc);
 
 
 static const struct pci_device_id sil_pci_tbl[] = {

@@ -196,6 +198,7 @@
 	.tf_read		= ata_tf_read,
 	.check_status		= ata_check_status,
 	.exec_command		= ata_exec_command,
+	.check_atapi_dma	= sil_check_atapi_dma,
 	.dev_select		= ata_std_dev_select,
 	.post_set_mode		= sil_post_set_mode,
 	.bmdma_setup            = ata_bmdma_setup,

@@ -289,6 +292,22 @@
 module_param(slow_down, int, 0444);
 MODULE_PARM_DESC(slow_down, "Sledgehammer used to work around random problems, by limiting commands to 15 sectors (0=off, 1=on)");
 
+static int sil_check_atapi_dma(struct ata_queued_cmd *qc)
+{
+	/* limit zero data size atapi commands to pio as certain sil */
+	/* chips seem to have trouble to perform dma for these commands */
+	if ( (qc->scsicmd != NULL) &&
+             (qc->scsicmd->sc_data_direction != DMA_NONE) &&
+	     (qc->nbytes == 0) )
+	{
+		/* do not allow dma */
+		return -1;
+	}
+
+	/* allow dma */
+	return 0;
+}
+
 
 static unsigned char sil_get_device_cache_line(struct pci_dev *pdev)
 {
#20 lore raw

Hello, Daniel.

Quoted 27 lines · Daniel Beichl
Quoted 17 lines

Okay, I've been thinking about it for some time. I think I know what's going on now. Those authentication related commands are issued by invoking ioctls on the device node. The cdrom driver receives the ioctls and issues respective SCSI commands for it. All those DVD auth commands either transfer or receive data from the device and thus specifies certain data direction when they're issued. libata selects command protocol accordingly.

It's all good and dandy till now but the problem is that those commands can be issued with data length of zero! This is allowed by the SCSI MMC standard and used to probe whether the command succeeds or not before taking further actions. When this happens, libata chooses command protocol according to the data direction, but has to feed 0-length data to the DMA engine. It seems sata_sil dma engine barfs if that happens.
Can you please add the following code snippet at the head of
atapi_xlat()?

Quoted 10 lines
    if (!nodata && !qc->nbytes) {
        printk("XXX forcing PIO for 0 length data cdb %02x\n",
            scmd->cmnd[0]);
        dump_stack();
        using_pio = 1;
    }

Also, do you mind cc'ing [email protected]?

Quoted 7 lines

Hi Tejun,

i inserted the code snippet you mentioned to atapi_xlat() in libata-scsi.c and the dvd authentication succeeds.

Please see the attached dmesg file for the generated stack dumps.

Good to know it works. :-)

Quoted 8 lines

The question is whether this is the right place to fix it, as this seems to limit all
drivers to pio if a zero data length command is transferred. It would make more sense to me if the individual driver decides this by performing a similar check in the check_atapi_dma function implemented by the
individual driver. I did this for the sata_sil driver in the attached patch.

The thing is that those commands don't transfer any data at all, so it doesn't really matter whether the data phase is specified as DMA or PIO.
ATA_PROT_ATAPI degenerates into ATA_PROT_ATAPI_NODATA if there is no
data to transfer (in ATA spec they share the same protocol state machine and the data request status bit dictates what actually happens).

I think this actually should be fixed in the cdrom driver. It shouldn't issue data command with 0 data length with data protocol. Can you test whether the attached patch works? Also, it seems we'll need to add a WARN_ON() in sr such that bugs like this can be caught more easily.

Thanks.

Signature · 1 line
tejun
drivers/ata/libata-scsi.c +0 -0
drivers/cdrom/cdrom.c +4 -1
index b36f44d..5a5639d 100644
@@ -1533,7 +1533,10 @@ void init_cdrom_command(struct packet_co
 		memset(buf, 0, len);
 	cgc->buffer = (char *) buf;
 	cgc->buflen = len;
-	cgc->data_direction = type;
+	if (len)
+		cgc->data_direction = type;
+	else
+		cgc->data_direction = CGC_DATA_NONE;
 	cgc->timeout = CDROM_DEF_TIMEOUT;
 }
#6 lore raw
In reply to Harald Dunkel

Hello, Harald.

Quoted 24 lines · Harald Dunkel

If I enter a movie DVD into my drive (Samsung SH-S183A, SATA) and run xine dvd:/dev/scd0 immediately (while the drive's LED is still blinking), then there is some timeout problem. kern.log says:

May  4 19:10:17 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr
0x0 action 0x2 frozen
May  4 19:10:17 pluto kernel: ata2.00: cmd
a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xa4 data 8 in
May  4 19:10:17 pluto kernel:          res
40/00:02:00:04:08/00:00:00:00:00/a0 Emask 0x4 (timeout)
May  4 19:10:17 pluto kernel: ata2: soft resetting port
May  4 19:10:24 pluto kernel: ata2: port is slow to respond, please be
patient (Status 0xf8)
May  4 19:10:47 pluto kernel: ata2: port failed to respond (30 secs,
Status 0xf8)
May  4 19:10:47 pluto kernel: ata2: SATA link up 1.5 Gbps (SStatus 113
SControl 310)
May  4 19:10:47 pluto kernel: ATA: abnormal status 0xF8 on port
0xffffc2000001a0c7
May  4 19:10:47 pluto last message repeated 5 times
May  4 19:11:17 pluto kernel: ata2.00: qc timeout (cmd 0xa1)
May  4 19:11:17 pluto kernel: ata2.00: failed to IDENTIFY (I/O error,

err_mask=0x4)

Quoted 8 lines
May  4 19:11:17 pluto kernel: ata2.00: revalidation failed (errno=-5)
May  4 19:11:17 pluto kernel: ata2: failed to recover some devices,
retrying in 5 secs
May  4 19:11:22 pluto kernel: ata2: hard resetting port
May  4 19:11:23 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2:
SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  4 19:11:23 pluto kernel: ata2.00: XXX: IDENTIFY
May  4 19:11:23 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000

[--snip--]

Quoted 2 lines
May  4 19:11:23 pluto kernel: ata2.00: configured for UDMA/33
May  4 19:11:23 pluto kernel: ata2: EH complete

The above is slightly different from the last one in that the device times out the following IDENTIFY command instead of sending corrupt data. The last log looked like...

ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in

          res 40/00:02:00:0c:00/00:00:00:00:00/a0 Emask 0x4 (timeout)

ata2: soft resetting port
CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310) ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0) ata2.00: revalidation failed (errno=-22)
ata2.00: disabled
ata2: EH complete

Note how the device is offlined after the error because it reported the wrong IDENTIFY data wheras IDENTIFY timeout was recovered properly (you can still access the device after the EH is complete).

Quoted 5 lines

Its pretty much reproducible. For the example above the DVD played at the end, but sometimes the DVD drive dies, and I have to reboot.

If I enter a data DVD and try to mount it without waiting, then I get

Quoted 7 lines

% mount /cdrom
mount: /dev/scd0 already mounted or /cdrom busy
% mount /cdrom
%

There is no message in kern.log in this case. On the second try it succeeds, as shown above.

This is probably because xine is opening the dvd device with O_NONBLOCK set. That tells the cdrom driver to skip readiness/integrity check. If it sets O_NONBLOCK, it's the application's responsibility to perform readiness check but it seems xine skips that and just issue REPORT KEY, which times out as the device takes more time to recognize the media than the specified timeout and kicks EH into action.

Please report the result of...

$ strace xine <whatever you need to play dvd> > out 2>&1
Quoted 3 lines

If I enter a data DVD without running anything, then it takes about 15 seconds till the LED goes off. Movie DVDs are a little bit faster: 12 secs. But I am sure this depends.

I think the waiting itself isn't a bug in the driver. It seems that the particular device needs a tad bit more time to recognize what's in it and xine seems to be not testing for device readiness before issuing other commands (needs verification tho).

What I'm primarily concerned about is the device getting disabled due to corrupt IDENTIFY data. Can you test whether the attached patch fixes the device disabling?

Thanks.

Signature · 1 line
tejun
author
#7 lore raw

Hi Tejun,

Your last patch contained zero bytes. Please check.

Quoted 5 lines · Tejun Heo

Please report the result of...

$ strace xine <whatever you need to play dvd> > out 2>&1

out.gz is >400KByte compressed. See private EMail. Below is the output in kern.log. This time it is the correct output (hopefully). After this the drive was unaccessible.

Regards

Harri
=============================================================

May  7 20:16:10 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
May  7 20:16:10 pluto kernel: ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in
May  7 20:16:10 pluto kernel:          res 40/00:00:00:10:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
May  7 20:16:10 pluto kernel: ata2: soft resetting port
May  7 20:16:10 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  7 20:16:10 pluto kernel: ata2.00: XXX: IDENTIFY
May  7 20:16:10 pluto kernel: 00: 6d58 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: 08: 35e8 5e2c c8b8 0c15  b87e 15c8 7e0c c8b8
May  7 20:16:10 pluto kernel: 10: 0c15 b87e 15c8 7e0c  e898 2c35 985e 66aa
May  7 20:16:10 pluto kernel: 18: 6e1e c8b8 0c15 cc0d  66bc 3d43 9ae8 6f71
May  7 20:16:10 pluto kernel: 20: b71a 63ac 090c bbd0  0166 a966 06a9 7e0c
May  7 20:16:10 pluto kernel: 28: c8b8 0c15 b87e 15c8  7e0c c8b8 0c15 985e
May  7 20:16:10 pluto kernel: 30: 35e8 512c e898 2e35  9a5e 35ee 5e2c e898
May  7 20:16:10 pluto kernel: 38: 2c35 985e 35e8 5e2c  e898 2c35 985e 35ef
May  7 20:16:10 pluto kernel: 40: 5e2f e8e0 2c4d 9826  3590 5e2c e898 2c35
May  7 20:16:10 pluto kernel: 48: 985e 35e8 5e2c e898  2a37 985e 3580 5e6c
May  7 20:16:10 pluto kernel: 50: e898 2c35 985e 75e8  1e2c e898 2c35 d85e
May  7 20:16:10 pluto kernel: 58: 31ef 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: 60: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: 68: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: 70: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: 78: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: 80: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: 88: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: 90: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: 98: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: a0: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: a8: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: b0: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: b8: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: c0: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: c8: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: d0: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: d8: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: e0: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: e8: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: f0: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: f8: 35e8 5e2c e898 2c35  985e 35e8 5e2c 743d
May  7 20:16:10 pluto kernel: ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0)
May  7 20:16:10 pluto kernel: ata2.00: revalidation failed (errno=-22)
May  7 20:16:10 pluto kernel: ata2.00: disabled
May  7 20:16:11 pluto kernel: ata2: EH complete
May  7 20:16:11 pluto kernel: cdrom: This disc doesn't have any tracks I recognize!
May  7 20:16:48 pluto kernel: Buffer I/O error on device sr0, logical block 0
May  7 20:16:48 pluto kernel: Buffer I/O error on device sr0, logical block 1

:
:

#8 lore raw
Quoted 3 lines · Harald Dunkel

Hi Tejun,

Your last patch contained zero bytes. Please check.

Sorry, new patch attached.

Quoted 10 lines
Quoted 5 lines · Tejun Heo

Please report the result of...

$ strace xine <whatever you need to play dvd> > out 2>&1

out.gz is >400KByte compressed. See private EMail. Below is the output in kern.log. This time it is the correct output (hopefully). After this the drive was unaccessible.

Thanks. xine was opening it the regular way. Can't tell why it times out. :(

Quoted 36 lines

=============================================================

May  7 20:16:10 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr
0x0 action 0x2 frozen
May  7 20:16:10 pluto kernel: ata2.00: cmd
a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in
May  7 20:16:10 pluto kernel:          res
40/00:00:00:10:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
May  7 20:16:10 pluto kernel: ata2: soft resetting port
May  7 20:16:10 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2:
SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  7 20:16:10 pluto kernel: ata2.00: XXX: IDENTIFY
May  7 20:16:10 pluto kernel: 00: 6d58 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: 08: 35e8 5e2c c8b8 0c15  b87e 15c8 7e0c c8b8
May  7 20:16:10 pluto kernel: 10: 0c15 b87e 15c8 7e0c  e898 2c35 985e 66aa
May  7 20:16:10 pluto kernel: 18: 6e1e c8b8 0c15 cc0d  66bc 3d43 9ae8 6f71
May  7 20:16:10 pluto kernel: 20: b71a 63ac 090c bbd0  0166 a966 06a9 7e0c
May  7 20:16:10 pluto kernel: 28: c8b8 0c15 b87e 15c8  7e0c c8b8 0c15 985e
May  7 20:16:10 pluto kernel: 30: 35e8 512c e898 2e35  9a5e 35ee 5e2c e898
May  7 20:16:10 pluto kernel: 38: 2c35 985e 35e8 5e2c  e898 2c35 985e 35ef
May  7 20:16:10 pluto kernel: 40: 5e2f e8e0 2c4d 9826  3590 5e2c e898 2c35
May  7 20:16:10 pluto kernel: 48: 985e 35e8 5e2c e898  2a37 985e 3580 5e6c
May  7 20:16:10 pluto kernel: 50: e898 2c35 985e 75e8  1e2c e898 2c35 d85e
May  7 20:16:10 pluto kernel: 58: 31ef 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: 60: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: 68: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: 70: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: 78: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: 80: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: 88: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: 90: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: 98: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: a0: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: a8: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: b0: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: b8: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: c0: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
Quoted 8 lines
May  7 20:16:10 pluto kernel: c8: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: d0: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: d8: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: e0: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: e8: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: f0: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: f8: 35e8 5e2c e898 2c35  985e 35e8 5e2c 743d
May  7 20:16:10 pluto kernel: ata2.00: failed to IDENTIFY (device

Yeap, this is what I was talking about. The whole IDENTIFY area seems to contain repeating pattern. Probably something to do with unflushed FIFO. The attached patch should allow EH to recover properly from this.
Please test.

Thanks.

Signature · 1 line
tejun
drivers/ata/libata-eh.c +1 -5
index 2bff9ad..82b212f 100644
@@ -2177,14 +2177,10 @@ static int ata_eh_recover(struct ata_por
 	ehc->tries[dev->devno]--;
 
 	switch (rc) {
-	case -EINVAL:
-		/* eeek, something went very wrong, give up */
-		ehc->tries[dev->devno] = 0;
-		break;
-
 	case -ENODEV:
 		/* device missing or wrong IDENTIFY data, schedule probing */
 		ehc->i.probe_mask |= (1 << dev->devno);
+	case -EINVAL:
 		/* give it just one more chance */
 		ehc->tries[dev->devno] = min(ehc->tries[dev->devno], 1);
 	case -EIO:
#22 lore raw
In reply to a message not in the archive

Hello,

Quoted 12 lines · Daniel Beichl

I gave the whole thing some thought. You suspected the sil dma engine to cause the issue, because it might only be usable with a certain command packet size.
If these commands result in packets their size is not zero. Not all packet commands transfer
data sectors, but they themselves have a size.

So i investigated libata and learnt from libata-scsi.c that nbytes is set to the size of the scsi
command corresponding to the atapi command that should be sent to the device near the end of atapi_xlat().

Quoted 5 lines

I added code to dump the packet size and data direction as set in the scsi command and noticed that the
controller freezes the port if a packet with the direction DMA_TO_DEVICE and a length smaller than ~60 bytes is issued, the command type does not matter at all.

Hmmmmm.... This is weird. < ~60 bytes? The zero-length protocol thing is a plain bug but this is something completely different. Can you test this with a different controller? Is the problem always reproducible?

Quoted 21 lines

I tried this with the cdrecord -atip option which generate packets of command cdb[0] = 0x00, length 60 and 16 in said direction. The first command succeeds, the second one triggers the dma bug.

The question now is, is the dma engine of the sil chip indeed the problem, or did i cover
another problem located somewhere else by restricting dma to packets not smaller than 60 bytes.
The datasheet of the sil3512 does not specify a lower limit for dma transfers.

It does not appear to be a modulo N issue either as i have seen the transfer of
packets of 12 or 16 bytes fail but then again packets of 60 bytes succeeds.

size result
==========
001100 fail
010000 fail
111100 succeed

Quoted 4 lines

A thing that crossed my mind was a timing issue. Perhaps the dmaing of < 60 bytes is that
fast that the interrupt that causes it is not yet handled correctly. But this is just a very wild guess.

I don't think that can happen. Controllers are required to queue interrupt till FIFO is flushed. Can you post dmesg after such errors?

Quoted 7 lines

I tried your latest patch and the dma bug did show up. I have attached a patch to this mail that
decides based on the dma direction and the command size in the sil_check_atapi_dma() routine
whether to allow dma or not. This fixed the dvd auth issue and the cdrecord -atip issue for me,
but i am pretty sure there is a better solution.

I'm not really sure what we're looking at and where the problem actually is. We need to find out more about this problem.

Signature · 1 line
tejun
#23 lore raw
Quoted 7 lines
Quoted 4 lines

A thing that crossed my mind was a timing issue. Perhaps the dmaing of < 60 bytes is that
fast that the interrupt that causes it is not yet handled correctly. But this is just a very wild guess.

I don't think that can happen. Controllers are required to queue interrupt till FIFO is flushed. Can you post dmesg after such errors?

Random finger in the air guess - the FIFO on the SIL DMA engine is 64 bytes long ? Perhaps this is something Jeff can query with his contacts at Silicon Image ?

Alan

#24 lore raw
Quoted 10 lines · Alan Cox
Quoted 6 lines
Quoted 4 lines

A thing that crossed my mind was a timing issue. Perhaps the dmaing of < 60 bytes is that
fast that the interrupt that causes it is not yet handled correctly. But this is just a very wild guess.

I don't think that can happen. Controllers are required to queue interrupt till FIFO is flushed. Can you post dmesg after such errors?

Random finger in the air guess - the FIFO on the SIL DMA engine is 64 bytes long ? Perhaps this is something Jeff can query with his contacts at Silicon Image ?

That sounds plausible. I have pretty good relationship with SIMG. I'll ask them.

Thanks.

Signature · 1 line
tejun
author
#9 lore raw
In reply to Tejun Heo

Hi Tejun,

Sorry to say, but after applying your patch it still doesn't work.

If I insert the DVD and wait before running xine, then I can watch it. But if I keep the tray open and run xine, then xine closes the tray. It gets stuck for some time, and then I get

% xine dvd:/dev/scd0
This is xine (X11 gui) - a free video player v0.99.5cvs.
(c) 2000-2006 The xine Team.
libdvdread: Using libdvdcss version 1.2.9 for DVD access
libdvdread: Could not open /dev/scd0 with libdvdcss.
libdvdread: Can't open /dev/scd0 for reading

kern.log says:

May  9 19:11:57 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
May  9 19:11:57 pluto kernel: ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xa4 data 12 in
May  9 19:11:57 pluto kernel:          res 40/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
May  9 19:11:57 pluto kernel: ata2: soft resetting port
May  9 19:12:05 pluto kernel: ata2: port is slow to respond, please be patient (Status 0xf8)
May  9 19:12:28 pluto kernel: ata2: port failed to respond (30 secs, Status 0xf8)
May  9 19:12:28 pluto kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  9 19:12:28 pluto kernel: ATA: abnormal status 0xF8 on port 0xffffc2000001a0c7
May  9 19:12:28 pluto last message repeated 5 times
May  9 19:12:58 pluto kernel: ata2.00: qc timeout (cmd 0xa1)
May  9 19:12:58 pluto kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
May  9 19:12:58 pluto kernel: ata2.00: revalidation failed (errno=-5)
May  9 19:12:58 pluto kernel: ata2: failed to recover some devices, retrying in 5 secs
May  9 19:13:03 pluto kernel: ata2: hard resetting port
May  9 19:13:03 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  9 19:13:03 pluto kernel: ata2.00: XXX: IDENTIFY
May  9 19:13:03 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 08: 0000 0000 2020 2020  2020 2020 2020 2020
May  9 19:13:03 pluto kernel: 10: 2020 2020 2020 2020  0000 0000 0000 5342
May  9 19:13:03 pluto kernel: 18: 3032 2020 2020 5453  5354 636f 7270 4344
May  9 19:13:03 pluto kernel: 20: 2f44 5644 5720 5348  2d53 3138 3341 2020
May  9 19:13:03 pluto kernel: 28: 2020 2020 2020 2020  2020 2020 2020 0000
May  9 19:13:03 pluto kernel: 30: 0000 0f00 0000 0200  0200 0006 0000 0000
May  9 19:13:03 pluto kernel: 38: 0000 0000 0000 0000  0000 0000 0000 0007
May  9 19:13:03 pluto kernel: 40: 0003 0078 0078 0078  0078 0000 0000 0000
May  9 19:13:03 pluto kernel: 48: 0000 0000 0000 0000  0602 0000 0068 0040
May  9 19:13:03 pluto kernel: 50: 0000 0000 0000 4000  4000 0000 0000 4000
May  9 19:13:03 pluto kernel: 58: 0407 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 60: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 68: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 70: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 78: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 80: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 88: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 90: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 98: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: a0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: a8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: b0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: b8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: c0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: c8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: d0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: d8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: e0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: e8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: f0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: f8: 0000 0000 0000 0000  0000 0000 0000 9ca5
May  9 19:13:04 pluto kernel: ata2.00: configured for UDMA/33
May  9 19:13:04 pluto kernel: ata2: EH complete

After that (the DVD is still in) I can rerun xine, and it works. This is reproducible using CSS DVDs. Using a DVD without CSS there is no such problem. It takes some time till the DVD is played, but there is no soft reset.

Using "gmplayer dvd://" I get the same problem.

You told me some time ago that you bought the same drive. Can you reproduce this problem? Please don't get me wrong, I am glad to support you by trying out new patches.

Regards

Harri

#10 lore raw

Hello,

Quoted 16 lines · Harald Dunkel

Hi Tejun,

Sorry to say, but after applying your patch it still doesn't work.

If I insert the DVD and wait before running xine, then I can watch it. But if I keep the tray open and run xine, then xine closes the tray. It gets stuck for some time, and then I get

% xine dvd:/dev/scd0
This is xine (X11 gui) - a free video player v0.99.5cvs.
(c) 2000-2006 The xine Team.
libdvdread: Using libdvdcss version 1.2.9 for DVD access
libdvdread: Could not open /dev/scd0 with libdvdcss.
libdvdread: Can't open /dev/scd0 for reading

Quoted 1 line

kern.log says:

[--snip--]

Quoted 2 lines
May  9 19:13:04 pluto kernel: ata2.00: configured for UDMA/33
May  9 19:13:04 pluto kernel: ata2: EH complete

The patch wasn't trying to fix the original problem. All it does it making sure the device itself doesn't get disabled after such an event - /dev/sr0 should be accessible even after garbled IDENTIFY. Can you try to trigger the condition where the device reports garbled IDENTIFY data and says...

ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0)

Without the patch, the device will be offlined so you can't use it anymore unless you issue manual rescan or unplug and replug the device.
With the patch, you should be able to access the device after EH is
complete.

Quoted 10 lines

After that (the DVD is still in) I can rerun xine, and it works. This is reproducible using CSS DVDs. Using a DVD without CSS there is no such problem. It takes some time till the DVD is played, but there is no soft reset.

Using "gmplayer dvd://" I get the same problem.

You told me some time ago that you bought the same drive. Can you reproduce this problem? Please don't get me wrong, I am glad to support you by trying out new patches.

I'd love to but I'm half globe away from my toys at the moment and not going back till the end of this month, so.... If this isn't resolved till I get back, I'll test myself.

It still could be that the dvd reading commands are issued with too short timeout. Does applying the attached patch make any difference?

Signature · 1 line
tejun
drivers/cdrom/cdrom.c +1 -1
index 3625a05..e404464 100644
@@ -341,7 +341,7 @@ static const char *mrw_address_space[] =
  * Another popular OS uses 7 seconds as the hard timeout for default
  * commands, so it is a good choice for us as well.
  */
-#define CDROM_DEF_TIMEOUT	(7 * HZ)
+#define CDROM_DEF_TIMEOUT	(15 * HZ)
 
 /* Not-exported routines. */
 static int open_for_data(struct cdrom_device_info * cdi);
author
#11 lore raw

Hi Tejun,

Setting the timeout to 15 did not help, either :-(. All your patches are still in, of course.

Regards

Harri
=======================================================================
kern.log says:

May 10 22:15:55 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
May 10 22:15:55 pluto kernel: ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in
May 10 22:15:55 pluto kernel:          res 40/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
May 10 22:15:55 pluto kernel: ata2: soft resetting port
May 10 22:15:55 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May 10 22:15:55 pluto kernel: ata2.00: XXX: IDENTIFY
May 10 22:15:55 pluto kernel: 00: 3b38 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: 08: edbe 8013 9ed8 33cd  d8a0 cd9e a033 9ed8
May 10 22:15:55 pluto kernel: 10: 33cd d8a0 cd9e a033  bef8 13ed f880 befc
May 10 22:15:55 pluto kernel: 18: b021 9ed8 33cd acd3  beea e37c cc88 50a9
May 10 22:15:55 pluto kernel: 20: d7c4 bbfa d733 edb0  3ebe c9b8 deff a033
May 10 22:15:55 pluto kernel: 28: 9ed8 33cd d8a0 cd9e  a033 9ed8 33cd f880
May 10 22:15:55 pluto kernel: 30: edbe 8f13 bef8 11ed  fa80 edb8 8013 bef8
May 10 22:15:55 pluto kernel: 38: 13ed f880 edbe 8013  bef8 13ed f880 edb9
May 10 22:15:55 pluto kernel: 40: 8010 be80 1395 f8f8  edc6 8013 bef8 13ed
May 10 22:15:55 pluto kernel: 48: f880 edbe 8013 bef8  15ef f880 edd6 8053
May 10 22:15:55 pluto kernel: 50: bef8 13ed f880 adbe  c013 bef8 13ed b880
May 10 22:15:55 pluto kernel: 58: e9b9 8013 bef8 13ed  f880 edbe 8013 bef8
May 10 22:15:55 pluto kernel: 60: 13ed f880 edbe 8013  bef8 13ed f880 edbe
May 10 22:15:55 pluto kernel: 68: 8013 bef8 13ed f880  edbe 8013 bef8 13ed
May 10 22:15:55 pluto kernel: 70: f880 edbe 8013 bef8  13ed f880 edbe 8013
May 10 22:15:55 pluto kernel: 78: bef8 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: 80: edbe 8013 bef8 13ed  f880 edbe 8013 bef8
May 10 22:15:55 pluto kernel: 88: 13ed f880 edbe 8013  bef8 13ed f880 edbe
May 10 22:15:55 pluto kernel: 90: 8013 bef8 13ed f880  edbe 8013 bef8 13ed
May 10 22:15:55 pluto kernel: 98: f880 edbe 8013 bef8  13ed f880 edbe 8013
May 10 22:15:55 pluto kernel: a0: bef8 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: a8: edbe 8013 bef8 13ed  f880 edbe 8013 bef8
May 10 22:15:55 pluto kernel: b0: 13ed f880 edbe 8013  bef8 13ed f880 edbe
May 10 22:15:55 pluto kernel: b8: 8013 bef8 13ed f880  edbe 8013 bef8 13ed
May 10 22:15:55 pluto kernel: c0: f880 edbe 8013 bef8  13ed f880 edbe 8013
May 10 22:15:55 pluto kernel: c8: bef8 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: d0: edbe 8013 bef8 13ed  f880 edbe 8013 bef8
May 10 22:15:55 pluto kernel: d8: 13ed f880 edbe 8013  bef8 13ed f880 edbe
May 10 22:15:55 pluto kernel: e0: 8013 bef8 13ed f880  edbe 8013 bef8 13ed
May 10 22:15:55 pluto kernel: e8: f880 edbe 8013 bef8  13ed f880 edbe 8013
May 10 22:15:55 pluto kernel: f0: bef8 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: f8: edbe 8013 bef8 13ed  f880 edbe 8013 225d
May 10 22:15:55 pluto kernel: ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0)
May 10 22:15:55 pluto kernel: ata2.00: revalidation failed (errno=-22)
May 10 22:15:55 pluto kernel: ata2.00: limiting speed to UDMA/33:PIO3
May 10 22:15:55 pluto kernel: ata2: failed to recover some devices, retrying in 5 secs
May 10 22:16:00 pluto kernel: ata2: hard resetting port
May 10 22:16:01 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May 10 22:16:01 pluto kernel: ata2.00: XXX: IDENTIFY
May 10 22:16:01 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 08: 0000 0000 2020 2020  2020 2020 2020 2020
May 10 22:16:01 pluto kernel: 10: 2020 2020 2020 2020  0000 0000 0000 5342
May 10 22:16:01 pluto kernel: 18: 3032 2020 2020 5453  5354 636f 7270 4344
May 10 22:16:01 pluto kernel: 20: 2f44 5644 5720 5348  2d53 3138 3341 2020
May 10 22:16:01 pluto kernel: 28: 2020 2020 2020 2020  2020 2020 2020 0000
May 10 22:16:01 pluto kernel: 30: 0000 0f00 0000 0200  0200 0006 0000 0000
May 10 22:16:01 pluto kernel: 38: 0000 0000 0000 0000  0000 0000 0000 0007
May 10 22:16:01 pluto kernel: 40: 0003 0078 0078 0078  0078 0000 0000 0000
May 10 22:16:01 pluto kernel: 48: 0000 0000 0000 0000  0602 0000 0068 0040
May 10 22:16:01 pluto kernel: 50: 0000 0000 0000 4000  4000 0000 0000 4000
May 10 22:16:01 pluto kernel: 58: 0407 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 60: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 68: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 70: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 78: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 80: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 88: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 90: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 98: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: a0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: a8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: b0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: b8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: c0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: c8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: d0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: d8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: e0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: e8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: f0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: f8: 0000 0000 0000 0000  0000 0000 0000 9ca5
May 10 22:16:01 pluto kernel: ata2.00: configured for UDMA/33
May 10 22:16:01 pluto kernel: ata2: EH complete
#12 lore raw

Hello,

Quoted 4 lines · Harald Dunkel

Hi Tejun,

Setting the timeout to 15 did not help, either :-(. All your patches are still in, of course.

Hmm... I'm out of ideas. I'll try it when I get back home.

Quoted 11 lines
May 10 22:15:55 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr
0x0 action 0x2 frozen
May 10 22:15:55 pluto kernel: ata2.00: cmd
a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in
May 10 22:15:55 pluto kernel:          res
40/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
May 10 22:15:55 pluto kernel: ata2: soft resetting port
May 10 22:15:55 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2:
SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May 10 22:15:55 pluto kernel: ata2.00: XXX: IDENTIFY
May 10 22:15:55 pluto kernel: 00: 3b38 13ed f880 edbe  8013 bef8 13ed f880

[--snip--]

Quoted 11 lines
May 10 22:15:55 pluto kernel: ata2.00: failed to IDENTIFY (device
reports illegal type, err_mask=0x0)
May 10 22:15:55 pluto kernel: ata2.00: revalidation failed (errno=-22)
May 10 22:15:55 pluto kernel: ata2.00: limiting speed to UDMA/33:PIO3
May 10 22:15:55 pluto kernel: ata2: failed to recover some devices,
retrying in 5 secs
May 10 22:16:00 pluto kernel: ata2: hard resetting port
May 10 22:16:01 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2:
SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May 10 22:16:01 pluto kernel: ata2.00: XXX: IDENTIFY
May 10 22:16:01 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000

[--snip--]

Quoted 2 lines
May 10 22:16:01 pluto kernel: ata2.00: configured for UDMA/33
May 10 22:16:01 pluto kernel: ata2: EH complete

Well, at least one thing worked. I'll push the patch upstream soon.

Thanks.

Signature · 1 line
tejun
author
#13 lore raw

Hi Tejun,

Quoted 10 lines · Tejun Heo

Hello,

Quoted 4 lines · Harald Dunkel

Hi Tejun,

Setting the timeout to 15 did not help, either :-(. All your patches are still in, of course.

Hmm... I'm out of ideas. I'll try it when I get back home.

I think I will survive for the next few days.

Quoted 5 lines
Quoted 2 lines
May 10 22:16:01 pluto kernel: ata2.00: configured for UDMA/33
May 10 22:16:01 pluto kernel: ata2: EH complete

Well, at least one thing worked. I'll push the patch upstream soon.

This was indeed a huge improvement. Before this patch I had to reboot to wake up the DVD drive.

Many thanx

Harri

#25 lore raw
In reply to a message not in the archive
Quoted 8 lines · Daniel Beichl
(quoted diff) +8 -0
+static int sil_check_atapi_dma(struct ata_queued_cmd *qc)
+{
+	/* limit atapi commands less than 60bytes to pio as certain sil */
+	/* chips seem to have trouble to perform dma for these commands */
+	if ( (qc->scsicmd != NULL) &&
+	     (qc->scsicmd->sc_data_direction == DMA_TO_DEVICE) &&
+	     (qc->scsicmd->request_bufflen < 60) )
+	{

Review

Quoted 10 lines
(quoted diff) +10 -0
+		ata_dev_printk( qc->dev, KERN_INFO, "reducing cmd %02x (direction=%d, len=%d) to pio\n", 
+			qc->cdb[0], 
+			qc->scsicmd->sc_data_direction, 
+			qc->scsicmd->request_bufflen );
+		/* do not allow dma */
+		return -1;
+	}
+
+	/* allow dma */
+	return 0;

Comments:

1) Return values are zero or one for this hook

2) There are two data bundling methods in SCSI: single-buffer and scatterlist. Further, SCSI is deprecating single-buffer method in favor of always using a scatterlist. Your patch needs to support scatterlist. Here is an example test found in libata-scsi.c that illustrates how
SCSI-aware code tests for and uses this:

        if (cmd->use_sg) {
                qc->__sg = (struct scatterlist *) cmd->request_buffer;

3) You need to always include a signoff line: http://linux.yyz.us/patch-format.html

Jeff

author
#14 lore raw
In reply to Tejun Heo

Hi Tejun,

Quoted 10 lines · Tejun Heo

Hello,

Quoted 4 lines · Harald Dunkel

Hi Tejun,

Setting the timeout to 15 did not help, either :-(. All your patches are still in, of course.

Hmm... I'm out of ideas. I'll try it when I get back home.

Any news about this? At the end I had the impression that this is a bug in the chip design. Is this correct?

Is there any chance to get the 60-byte patch into the kernel?

Regards

Harri

#15 lore raw
Quoted 11 lines · Harald Dunkel
Quoted 8 lines
Quoted 4 lines · Harald Dunkel

Hi Tejun,

Setting the timeout to 15 did not help, either :-(. All your patches are still in, of course.

Hmm... I'm out of ideas. I'll try it when I get back home.

Any news about this? At the end I had the impression that this is a bug in the chip design. Is this correct?

I can't reproduce that with sil3112 and the same SH-S183A. I don't know what's going on here. Mine behaves really good but yours seems to be causing all sorts of problems.

Quoted 1 line

Is there any chance to get the 60-byte patch into the kernel?

We still don't know what's going on so....

Signature · 1 line
tejun