You are not logged in.

Pages: 1

#1 2010-07-17 09:43:49

mkkot
Member
From: Poland
Registered: 2009-12-20
Posts: 287

Problems with negotiating DMA transfer mode

Hi folks,

Few days ago I ran my system and started some work (look carefully at the time):

Jul 15 21:18:01 linux -- MARK --
Jul 15 21:38:01 linux -- MARK --

In background I made an update:

[2010-07-15 21:52] Running 'pacman -Syu'
[2010-07-15 21:52] synchronizing package lists
[2010-07-15 21:52] starting full system upgrade
[2010-07-15 21:56] upgraded udev (159-1 -> 160-1)
[2010-07-15 21:56] upgraded device-mapper (2.02.69-1 -> 2.02.70-1)
[2010-07-15 21:56] upgraded cryptsetup (1.1.2-1 -> 1.1.3-1)
[2010-07-15 21:56] upgraded eventlog (0.2.9-1 -> 0.2.12-1)
[2010-07-15 21:56] upgraded initscripts (2010.06-2 -> 2010.07-1)
[2010-07-15 21:56] upgraded libssh (0.4.4-1 -> 0.4.5-1)
[2010-07-15 21:56] upgraded linux-firmware (20100606-1 -> 20100623-2)
[2010-07-15 21:56] upgraded lucene (2.9.2-1 -> 2.9.3-1)
[2010-07-15 21:56] upgraded lvm2 (2.02.69-1 -> 2.02.70-1)
[2010-07-15 21:56] upgraded mkinitcpio (0.6.6-1 -> 0.6.7-1)
[2010-07-15 21:56] upgraded sip (4.10.2-1 -> 4.10.3-1)
[2010-07-15 21:56] upgraded pyqt (4.7.3-1 -> 4.7.4-2)
[2010-07-15 21:56] upgraded qscintilla (2.4.3-1 -> 2.4.4-2)
[2010-07-15 21:56] upgraded whois (5.0.5-1 -> 5.0.6-1)

Few minutes after upgrade KDE's apps refused to write to configuration files. Ext4 has probably remounted to read-only. Why? Well, maybe because of this:

Jul 15 21:56:12 linux kernel: ata3: hard resetting link
Jul 15 21:56:12 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:56:13 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:56:13 linux kernel: ata3.00: configured for UDMA/133
Jul 15 21:56:13 linux kernel: ata3: EH complete
Jul 15 21:56:44 linux kernel: ata3: hard resetting link
Jul 15 21:56:44 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:56:45 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:56:45 linux kernel: ata3.00: configured for UDMA/133
Jul 15 21:56:45 linux kernel: ata3: EH complete
Jul 15 21:56:46 linux kernel: ata3: hard resetting link
Jul 15 21:56:46 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:56:46 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:56:46 linux kernel: ata3.00: configured for UDMA/133
Jul 15 21:56:46 linux kernel: ata3: EH complete
Jul 15 21:56:46 linux kernel: ata3: limiting SATA link speed to 1.5 Gbps
Jul 15 21:56:46 linux kernel: ata3: hard resetting link
Jul 15 21:56:46 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:56:47 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:56:47 linux kernel: ata3.00: configured for UDMA/133
Jul 15 21:56:47 linux kernel: ata3: EH complete
Jul 15 21:56:47 linux kernel: ata3: hard resetting link
Jul 15 21:56:47 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:56:47 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:56:47 linux kernel: ata3.00: configured for UDMA/133
Jul 15 21:56:47 linux kernel: ata3: EH complete
Jul 15 21:56:48 linux kernel: ata3: hard resetting link
Jul 15 21:56:48 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:56:48 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:56:48 linux kernel: ata3.00: configured for UDMA/133
Jul 15 21:56:48 linux kernel: ata3: EH complete
Jul 15 21:56:52 linux kernel: ata3: hard resetting link
Jul 15 21:56:52 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:56:53 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:56:53 linux kernel: ata3.00: configured for UDMA/133
Jul 15 21:56:53 linux kernel: ata3: EH complete
Jul 15 21:59:21 linux kernel: ata3.00: limiting speed to UDMA/100:PIO4
Jul 15 21:59:21 linux kernel: ata3: hard resetting link
Jul 15 21:59:21 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:59:21 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:59:21 linux kernel: ata3.00: configured for UDMA/100
Jul 15 21:59:21 linux kernel: ata3: EH complete
Jul 15 21:59:27 linux kernel: ata3: hard resetting link
Jul 15 21:59:27 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:59:28 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:59:28 linux kernel: ata3.00: configured for UDMA/100
Jul 15 21:59:28 linux kernel: ata3: EH complete
Jul 15 21:59:32 linux kernel: ata3: hard resetting link
Jul 15 21:59:32 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:59:33 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:59:33 linux kernel: ata3.00: configured for UDMA/100
Jul 15 21:59:33 linux kernel: ata3: EH complete
Jul 15 21:59:38 linux kernel: ata3: hard resetting link
Jul 15 21:59:38 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:59:38 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:59:38 linux kernel: ata3.00: configured for UDMA/100
Jul 15 21:59:38 linux kernel: ata3: EH complete
Jul 15 21:59:43 linux kernel: ata3.00: limiting speed to UDMA/33:PIO4
Jul 15 21:59:43 linux kernel: ata3: hard resetting link
Jul 15 21:59:43 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 21:59:43 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 21:59:43 linux kernel: ata3.00: configured for UDMA/33
Jul 15 21:59:43 linux kernel: ata3: EH complete
Jul 15 22:00:53 linux kernel: ata3: hard resetting link
Jul 15 22:00:53 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 22:00:53 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 22:00:53 linux kernel: ata3.00: configured for UDMA/33
Jul 15 22:00:53 linux kernel: ata3: EH complete
Jul 15 22:00:53 linux kernel: ata3: hard resetting link
Jul 15 22:00:53 linux kernel: ata3: nv: skipping hardreset on occupied port
Jul 15 22:00:54 linux kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jul 15 22:00:54 linux kernel: ata3.00: configured for UDMA/33
Jul 15 22:00:54 linux kernel: ata3: EH complete
and so on...

Of course I wasn't that smart at the beginning, so I though "uhm, it's some upgrade-related issue, let's just reboot". After the reboot, system before running /etc/rc.d/ scripts, shows previously mentioned UDMA message in a loop, scrolling it very fast. After some time (it depends of transfer mode negotiating success), system finally boots and there are two ways it can behave: 1. "Run fdisk manually..." or 2. it starts KDE but after a while there is another message "can't write to ./kde4/share/config/kapprc".

There is another thing to mention. When the system is negotiating transfer mode, it logs errors into hard disk's SMART:

SMART Error Log Version: 1
ATA Error Count: 153 (device log contains only the most recent five errors)
    CR = Command Register [HEX]
    FR = Features Register [HEX]
    SC = Sector Count Register [HEX]
    SN = Sector Number Register [HEX]
    CL = Cylinder Low Register [HEX]
    CH = Cylinder High Register [HEX]
    DH = Device/Head Register [HEX]
    DC = Device Command Register [HEX]
    ER = Error register [HEX]
    ST = Status register [HEX]
Powered_Up_Time is measured from power on, and printed as
DDd+hh:mm:SS.sss where DD=days, hh=hours, mm=minutes,
SS=sec, and sss=millisec. It "wraps" after 49.710 days.

Error 153 occurred at disk power-on lifetime: 7893 hours (328 days + 21 hours)
  When the command that caused the error occurred, the device was active or idle.

  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  84 51 08 7e 00 00 e0  Error: ICRC, ABRT at LBA = 0x0000007e = 126

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  ca 00 08 7e 00 00 e0 00      00:21:13.000  WRITE DMA
  c8 00 88 6e 36 15 e0 00      00:21:13.000  READ DMA
  ca 00 08 7e 00 44 e0 00      00:21:13.000  WRITE DMA
  ec 00 00 00 00 00 a0 00      00:21:13.000  IDENTIFY DEVICE
  ef 03 46 00 00 00 a0 00      00:21:13.000  SET FEATURES [Set transfer mode]

Error 152 occurred at disk power-on lifetime: 7893 hours (328 days + 21 hours)
  When the command that caused the error occurred, the device was active or idle.

  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  84 51 18 8e 52 7a e0  Error: ICRC, ABRT at LBA = 0x007a528e = 8016526

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  ca 00 18 8e 52 7a e0 00      00:21:09.000  WRITE DMA
  ca 00 08 7e 52 7a e0 00      00:21:09.000  WRITE DMA
  ca 00 08 76 ff 0a e0 00      00:21:09.000  WRITE DMA
  ca 00 08 7e 67 9d e0 00      00:21:09.000  WRITE DMA
  ca 00 08 7e 00 44 e0 00      00:21:09.000  WRITE DMA

Error 151 occurred at disk power-on lifetime: 7893 hours (328 days + 21 hours)
  When the command that caused the error occurred, the device was active or idle.

  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  84 51 58 fe 00 40 e0  Error: ICRC, ABRT at LBA = 0x004000fe = 4194558

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  ca 00 58 fe 00 40 e0 00      00:18:46.938  WRITE DMA
  ca 00 08 86 25 00 e0 00      00:18:46.938  WRITE DMA
  ca 00 08 fe 13 00 e0 00      00:18:46.938  WRITE DMA
  ca 00 08 4e 13 00 e0 00      00:18:46.938  WRITE DMA
  ca 00 80 0e 0d 00 e0 00      00:18:46.938  WRITE DMA

Error 150 occurred at disk power-on lifetime: 7893 hours (328 days + 21 hours)
  When the command that caused the error occurred, the device was active or idle.

  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  84 51 08 86 00 00 e0  Error: ICRC, ABRT at LBA = 0x00000086 = 134

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  ca 00 08 86 00 00 e0 00      00:18:21.375  WRITE DMA
  c8 00 08 06 2f c0 e0 00      00:17:54.625  READ DMA
  c8 00 08 0e 2e c0 e0 00      00:17:54.625  READ DMA
  c8 00 08 fe 2e c0 e0 00      00:17:54.625  READ DMA
  c8 00 08 7e 2e c0 e0 00      00:17:54.625  READ DMA

I had such errors before but there were I dunno, maybe five of them. And I'm still using some other linux system (actually it's 4 years old) without any problems. Now I'm writing from Parted Magic live cd, which negotiated transfer mode as follows:

root@PartedMagic:~# hdparm -i /dev/sda

/dev/sda:

 Model=SAMSUNG SP2504C, FwRev=VT100-41, SerialNo=S09QJ1LL402181
 Config={ Fixed }
 RawCHS=16383/16/63, TrkSize=34902, SectSize=554, ECCbytes=4
 BuffType=DualPortCache, BuffSize=8192kB, MaxMultSect=16, MultSect=16
 CurCHS=16383/16/63, CurSects=16514064, LBA=yes, LBAsects=488395055
 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
 PIO modes:  pio0 pio1 pio2 pio3 pio4 
 DMA modes:  mdma0 mdma1 mdma2 
 UDMA modes: udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
 AdvancedPM=no WriteCache=enabled
 Drive conforms to: unknown:  ATA/ATAPI-1,2,3,4,5,6,7

 * signifies the current active mode

I have also another similar disk, the only difference is firmware version:

root@PartedMagic:~# hdparm -i /dev/sdb

/dev/sdb:

 Model=SAMSUNG SP2504C, FwRev=VT100-50, SerialNo=S09QJ1GLB15632
 Config={ Fixed }
 RawCHS=16383/16/63, TrkSize=34902, SectSize=554, ECCbytes=4
 BuffType=DualPortCache, BuffSize=8192kB, MaxMultSect=16, MultSect=16
 CurCHS=16383/16/63, CurSects=16514064, LBA=yes, LBAsects=488397168
 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
 PIO modes:  pio0 pio1 pio2 pio3 pio4 
 DMA modes:  mdma0 mdma1 mdma2 
 UDMA modes: udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
 AdvancedPM=no WriteCache=enabled
 Drive conforms to: unknown:  ATA/ATAPI-1,2,3,4,5,6,7

 * signifies the current active mode

Of course both of them are perfectly fine, I just ran smartctl -t long. SMART's error log exists only on the disk where archlinux is located.

Actually I'n not quite sure which ata controller number marks which drive. Archlinux lies on sda.

Look:

cat /media/sda5/var/log/messages.log |grep ata1.00
Jul 14 09:38:50 linux kernel: ata1.00: ATAPI: LITE-ON DVDRW SHW-1635S, YS0Z, max UDMA/66
Jul 16 16:26:17 linux kernel: ata1.00: ATA-7: SAMSUNG SP2504C, VT100-41, max UDMA7 (this is the one with archlinux)

cat /media/sda5/var/log/messages.log |grep ata3.00
Jul 14 09:38:50 linux kernel: ata3.00: ATA-7: SAMSUNG SP2504C, VT100-41, max UDMA7 (this is the one with archlinux)
Jul 16 16:26:17 linux kernel: ata3.00: ATA-7: SAMSUNG SP2504C, VT100-50, max UDMA7

They have switched after upgrade? I have no idea how to interpret this. There is also a SATA DVD writer, not listed here (dunno why).

Both hard disks support SATA 3Gb mode as well as my chipset which is nForce 430.


Here is some dmesg output from live cd you migh find useful:

root@PartedMagic:~# dmesg |grep ata
 BIOS-e820: 000000007fff3000 - 0000000080000000 (ACPI data)
Memory: 2067624k/2097088k available (6813k kernel code, 29072k reserved, 3273k data, 584k init, 1187784k highmem)
      .data : 0xc16a7632 - 0xc19d9d44   (3273 kB)
libata version 3.00 loaded.
sata_nv 0000:00:08.0: version 3.5
sata_nv 0000:00:08.0: setting latency timer to 64
scsi2 : sata_nv
scsi3 : sata_nv
ata1: SATA max UDMA/133 cmd 0x9f0 ctl 0xbf0 bmdma 0xc800 irq 11
ata2: SATA max UDMA/133 cmd 0x970 ctl 0xb70 bmdma 0xc808 irq 11
sata_nv 0000:00:08.1: setting latency timer to 64
scsi4 : sata_nv
scsi5 : sata_nv
ata3: SATA max UDMA/133 cmd 0x9e0 ctl 0xbe0 bmdma 0xdc00 irq 10
ata4: SATA max UDMA/133 cmd 0x960 ctl 0xb60 bmdma 0xdc08 irq 10
pata_amd 0000:00:06.0: version 0.4.1
pata_amd 0000:00:06.0: setting latency timer to 64
scsi6 : pata_amd
scsi7 : pata_amd
ata5: PATA max UDMA/133 cmd 0x1f0 ctl 0x3f6 bmdma 0xf000 irq 14
ata6: PATA max UDMA/133 cmd 0x170 ctl 0x376 bmdma 0xf008 irq 15
usbcore: registered new interface driver ums-datafab
ata5.00: ATAPI: LITE-ON DVDRW SHW-1635S, YS0Z, max UDMA/66
ata5: nv_mode_filter: 0x1f39f&0x1f3ff->0x1f39f, BIOS=0x1f000 (0xc5000000) ACPI=0x0
ata5.00: configured for UDMA/66
ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata1.00: HPA detected: current 488395055, native 488397168
ata1.00: ATA-7: SAMSUNG SP2504C, VT100-41, max UDMA7
ata1.00: 488395055 sectors, multi 16: LBA48 NCQ (depth 0/32)
ata3.00: ATA-7: SAMSUNG SP2504C, VT100-50, max UDMA7
ata3.00: 488397168 sectors, multi 16: LBA48 NCQ (depth 0/32)
ata1.00: configured for UDMA/133
ata3.00: configured for UDMA/133
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata2.00: ATAPI: PIONEER DVD-RW  DVR-212, 1.28, max UDMA/66
ata2.00: configured for UDMA/66
ata4: SATA link down (SStatus 0 SControl 300)
ata6: port disabled. ignoring.
EXT4-fs (sda5): mounted filesystem with ordered data mode
REISERFS (device sda6): using ordered data mode
EXT3-fs (sda10): mounted filesystem with writeback data mode
EXT3-fs (sda10): mounted filesystem with writeback data mode
EXT4-fs (sda5): mounted filesystem with ordered data mode

Any help appreciated.

Offline

#2 2010-07-19 17:24:46

djgera
Developer
From: Buenos Aires - Argentina
Registered: 2008-12-24
Posts: 723
Website

Re: Problems with negotiating DMA transfer mode

ICRC error implies in most cases:
1) Cable problem
2) Power failure

Offline

#3 2010-07-19 18:01:45

mkkot
Member
From: Poland
Registered: 2009-12-20
Posts: 287

Re: Problems with negotiating DMA transfer mode

Yeah, but here's the trick: it stopped working in the same minute as when the update finished ;]

Offline

#4 2010-07-20 08:21:34

JGC
Developer
Registered: 2003-12-03
Posts: 1,664

Re: Problems with negotiating DMA transfer mode

I had a disk crash in the same minute an upgrade was finished. The packages in your log don't include anything related to your problem. The only thing related is that a system update produces massive I/O, which can be enough to kill a setup that is barely working.

Offline

#5 2010-07-20 10:36:19

mkkot
Member
From: Poland
Registered: 2009-12-20
Posts: 287

Re: Problems with negotiating DMA transfer mode

Seems it started to work today, sorry for bothering you.

Offline

Pages: 1

Board footer

Powered by FluxBB