Linux Archive

Linux Archive (http://www.linux-archive.org/)
-   Gentoo User (http://www.linux-archive.org/gentoo-user/)
-   -   Noisy dd operation (http://www.linux-archive.org/gentoo-user/673863-noisy-dd-operation.html)

Michael Mol 06-17-2012 11:27 PM

Noisy dd operation
 
So, I'm using dd to write the Gentoo LiveDVD ISO directly to an SDHC
card. I was wondering why the transfer rate had slowed from 20MB/s to
6MB/s, so I ran 'sudo tail -f /var/log/messages' to see if there were
I/O errors slowing things down.

What I found was a flood-stream of message blocks that look like this:

Jun 17 19:21:18 saffron kernel: [39023.458632] usb-storage:
queuecommand_lck called
Jun 17 19:21:18 saffron kernel: [39023.458670] usb-storage: *** thread awakened.
Jun 17 19:21:18 saffron kernel: [39023.458685] usb-storage: Command
WRITE_10 (10 bytes)
Jun 17 19:21:18 saffron kernel: [39023.458687] usb-storage: 2a 00 00
2b f3 80 00 00 f0 00
Jun 17 19:21:18 saffron kernel: [39023.458694] usb-storage:
rts51x_invoke_transport: <---
Jun 17 19:21:18 saffron kernel: [39023.458697] usb-storage:
rts51x_invoke_transport: working scsi,
intf->pm_usage_cnt:1,power.usage:1
Jun 17 19:21:18 saffron kernel: [39023.458701] usb-storage: Bulk
Command S 0x43425355 T 0x34ef L 122880 F 0 Trg 0 LUN 0 CL 10
Jun 17 19:21:18 saffron kernel: [39023.458704] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Jun 17 19:21:18 saffron kernel: [39023.458759] usb-storage: Status
code 0; transferred 31/31
Jun 17 19:21:18 saffron kernel: [39023.458761] usb-storage: -- transfer complete
Jun 17 19:21:18 saffron kernel: [39023.458763] usb-storage: Bulk
command transfer result=0
Jun 17 19:21:18 saffron kernel: [39023.458766] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 18 entries
Jun 17 19:21:18 saffron kernel: [39023.486031] usb-storage: Status
code 0; transferred 122880/122880
Jun 17 19:21:18 saffron kernel: [39023.486035] usb-storage: -- transfer complete
Jun 17 19:21:18 saffron kernel: [39023.486037] usb-storage: Bulk data
transfer result 0x0
Jun 17 19:21:18 saffron kernel: [39023.486039] usb-storage: Attempting
to get CSW...
Jun 17 19:21:18 saffron kernel: [39023.486042] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Jun 17 19:21:18 saffron kernel: [39023.491787] usb-storage: Status
code 0; transferred 13/13
Jun 17 19:21:18 saffron kernel: [39023.491790] usb-storage: -- transfer complete
Jun 17 19:21:18 saffron kernel: [39023.491793] usb-storage: Bulk
status result = 0
Jun 17 19:21:18 saffron kernel: [39023.491795] usb-storage: Bulk
Status S 0x53425355 T 0x34ef R 0 Stat 0x0
Jun 17 19:21:18 saffron kernel: [39023.491800] usb-storage:
rts51x_invoke_transport: state:2
Jun 17 19:21:18 saffron kernel: [39023.491802] usb-storage:
rts51x_modi_suspend_timer: <---, state:2
Jun 17 19:21:18 saffron kernel: [39023.491805] usb-storage:
rts51x_modi_suspend_timer: --->
Jun 17 19:21:18 saffron kernel: [39023.491807] usb-storage:
rts51x_invoke_transport: --->
Jun 17 19:21:18 saffron kernel: [39023.491809] usb-storage: scsi cmd
done, result=0x0
Jun 17 19:21:18 saffron kernel: [39023.491815] usb-storage: *** thread sleeping.

... Any idea what kernel configuration flag I may have enabled to
cause these to be continually generated? My first guess would be
something like 'kernel lock debugging'...if that's what I'm seeing
here, where would I go to file a bug report against the usb-storage
subsystem?

--
:wq

Alan McKinnon 06-17-2012 11:58 PM

Noisy dd operation
 
On Sun, 17 Jun 2012 19:27:36 -0400
Michael Mol <mikemol@gmail.com> wrote:

> So, I'm using dd to write the Gentoo LiveDVD ISO directly to an SDHC
> card. I was wondering why the transfer rate had slowed from 20MB/s to
> 6MB/s, so I ran 'sudo tail -f /var/log/messages' to see if there were
> I/O errors slowing things down.
>
> What I found was a flood-stream of message blocks that look like this:
>
> Jun 17 19:21:18 saffron kernel: [39023.458632] usb-storage:
> queuecommand_lck called
> Jun 17 19:21:18 saffron kernel: [39023.458670] usb-storage: ***
> thread awakened. Jun 17 19:21:18 saffron kernel: [39023.458685]
> usb-storage: Command WRITE_10 (10 bytes)
> Jun 17 19:21:18 saffron kernel: [39023.458687] usb-storage: 2a 00 00
> 2b f3 80 00 00 f0 00
> Jun 17 19:21:18 saffron kernel: [39023.458694] usb-storage:
> rts51x_invoke_transport: <---
> Jun 17 19:21:18 saffron kernel: [39023.458697] usb-storage:
> rts51x_invoke_transport: working scsi,
> intf->pm_usage_cnt:1,power.usage:1
> Jun 17 19:21:18 saffron kernel: [39023.458701] usb-storage: Bulk
> Command S 0x43425355 T 0x34ef L 122880 F 0 Trg 0 LUN 0 CL 10
> Jun 17 19:21:18 saffron kernel: [39023.458704] usb-storage:
> usb_stor_bulk_transfer_buf: xfer 31 bytes
> Jun 17 19:21:18 saffron kernel: [39023.458759] usb-storage: Status
> code 0; transferred 31/31
> Jun 17 19:21:18 saffron kernel: [39023.458761] usb-storage: --
> transfer complete Jun 17 19:21:18 saffron kernel: [39023.458763]
> usb-storage: Bulk command transfer result=0
> Jun 17 19:21:18 saffron kernel: [39023.458766] usb-storage:
> usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 18 entries
> Jun 17 19:21:18 saffron kernel: [39023.486031] usb-storage: Status
> code 0; transferred 122880/122880
> Jun 17 19:21:18 saffron kernel: [39023.486035] usb-storage: --
> transfer complete Jun 17 19:21:18 saffron kernel: [39023.486037]
> usb-storage: Bulk data transfer result 0x0
> Jun 17 19:21:18 saffron kernel: [39023.486039] usb-storage: Attempting
> to get CSW...
> Jun 17 19:21:18 saffron kernel: [39023.486042] usb-storage:
> usb_stor_bulk_transfer_buf: xfer 13 bytes
> Jun 17 19:21:18 saffron kernel: [39023.491787] usb-storage: Status
> code 0; transferred 13/13
> Jun 17 19:21:18 saffron kernel: [39023.491790] usb-storage: --
> transfer complete Jun 17 19:21:18 saffron kernel: [39023.491793]
> usb-storage: Bulk status result = 0
> Jun 17 19:21:18 saffron kernel: [39023.491795] usb-storage: Bulk
> Status S 0x53425355 T 0x34ef R 0 Stat 0x0
> Jun 17 19:21:18 saffron kernel: [39023.491800] usb-storage:
> rts51x_invoke_transport: state:2
> Jun 17 19:21:18 saffron kernel: [39023.491802] usb-storage:
> rts51x_modi_suspend_timer: <---, state:2
> Jun 17 19:21:18 saffron kernel: [39023.491805] usb-storage:
> rts51x_modi_suspend_timer: --->
> Jun 17 19:21:18 saffron kernel: [39023.491807] usb-storage:
> rts51x_invoke_transport: --->
> Jun 17 19:21:18 saffron kernel: [39023.491809] usb-storage: scsi cmd
> done, result=0x0
> Jun 17 19:21:18 saffron kernel: [39023.491815] usb-storage: ***
> thread sleeping.
>
> ... Any idea what kernel configuration flag I may have enabled to
> cause these to be continually generated? My first guess would be
> something like 'kernel lock debugging'...if that's what I'm seeing
> here, where would I go to file a bug report against the usb-storage
> subsystem?
>

6M is what you should expect from a good Class 6 SDHC card, and those
are quite rare in consumer shops (few carry better than Class 4 in my
experience). Writes start very fast (it's going into the kernel buffer)
then gradually slow down to the card's actual speed, which is what you
appear to be seeing.

20M write speed would be a Class 20, which doesn't exist yet :-)


But what is your actual query? About the write speed?

Or about the presence of the messages?



--
Alan McKinnnon
alan.mckinnon@gmail.com

Michael Mol 06-18-2012 01:03 AM

Noisy dd operation
 
On Sun, Jun 17, 2012 at 7:58 PM, Alan McKinnon <alan.mckinnon@gmail.com> wrote:
> On Sun, 17 Jun 2012 19:27:36 -0400
> Michael Mol <mikemol@gmail.com> wrote:
>
>> So, I'm using dd to write the Gentoo LiveDVD ISO directly to an SDHC
>> card. I was wondering why the transfer rate had slowed from 20MB/s to
>> 6MB/s, so I ran 'sudo tail -f /var/log/messages' to see if there were
>> I/O errors slowing things down.
>>
>> What I found was a flood-stream of message blocks that look like this:

[snip]

>> ... Any idea what kernel configuration flag I may have enabled to
>> cause these to be continually generated? My first guess would be
>> something like 'kernel lock debugging'...if that's what I'm seeing
>> here, where would I go to file a bug report against the usb-storage
>> subsystem?
>>
>
> 6M is what you should expect from a good Class 6 SDHC card, and those
> are quite rare in consumer shops (few carry better than Class 4 in my
> experience).

Yeah, for a given class N, N MB/s is minimum certified transfer rate.
Though they probably don't take cover block reflashing in that...

> Writes start very fast (it's going into the kernel buffer)
> then gradually slow down to the card's actual speed, which is what you
> appear to be seeing.

That kernel buffer would have been a gigabyte or two in size, and I
don't remember noticing that while watching in htop.

>
> 20M write speed would be a Class 20, which doesn't exist yet :-)

Well, more to the point there's no certification level for it. Devices
can exceed their certification level.

> But what is your actual query? About the write speed?

No, not really. TBH, I wasn't expecting to be able to consistently
write quickly to the beginning of the card, but slowly at the end; I
wanted to make sure the card wasn't going bad given the abruptness of
the change. Actually, the more I think about it, I think it happened
at the 2GB boundary, where some funky pin logic changes. (And where SD
becomes SDHC). So I think that's where the performance shifted. Maybe
I'll invest in a bunch of fast 2G cards, if it means the performance
is consistent, and I'd still fit just under 200 shots.

>
> Or about the presence of the messages?

Yeah, it's the messages I was curious about.

--
:wq

Volker Armin Hemmann 06-18-2012 04:24 PM

Noisy dd operation
 
Am Sonntag, 17. Juni 2012, 19:27:36 schrieb Michael Mol:
> So, I'm using dd to write the Gentoo LiveDVD ISO directly to an SDHC
> card. I was wondering why the transfer rate had slowed from 20MB/s to
> 6MB/s, so I ran 'sudo tail -f /var/log/messages' to see if there were
> I/O errors slowing things down.
>
> What I found was a flood-stream of message blocks that look like this:
>
> Jun 17 19:21:18 saffron kernel: [39023.458632] usb-storage:
> queuecommand_lck called
> Jun 17 19:21:18 saffron kernel: [39023.458670] usb-storage: *** thread
> awakened. Jun 17 19:21:18 saffron kernel: [39023.458685] usb-storage:
> Command WRITE_10 (10 bytes)
> Jun 17 19:21:18 saffron kernel: [39023.458687] usb-storage: 2a 00 00
> 2b f3 80 00 00 f0 00
> Jun 17 19:21:18 saffron kernel: [39023.458694] usb-storage:
> rts51x_invoke_transport: <---
> Jun 17 19:21:18 saffron kernel: [39023.458697] usb-storage:
> rts51x_invoke_transport: working scsi,
> intf->pm_usage_cnt:1,power.usage:1
> Jun 17 19:21:18 saffron kernel: [39023.458701] usb-storage: Bulk
> Command S 0x43425355 T 0x34ef L 122880 F 0 Trg 0 LUN 0 CL 10
> Jun 17 19:21:18 saffron kernel: [39023.458704] usb-storage:
> usb_stor_bulk_transfer_buf: xfer 31 bytes
> Jun 17 19:21:18 saffron kernel: [39023.458759] usb-storage: Status
> code 0; transferred 31/31
> Jun 17 19:21:18 saffron kernel: [39023.458761] usb-storage: -- transfer
> complete Jun 17 19:21:18 saffron kernel: [39023.458763] usb-storage: Bulk
> command transfer result=0
> Jun 17 19:21:18 saffron kernel: [39023.458766] usb-storage:
> usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 18 entries
> Jun 17 19:21:18 saffron kernel: [39023.486031] usb-storage: Status
> code 0; transferred 122880/122880
> Jun 17 19:21:18 saffron kernel: [39023.486035] usb-storage: -- transfer
> complete Jun 17 19:21:18 saffron kernel: [39023.486037] usb-storage: Bulk
> data transfer result 0x0
> Jun 17 19:21:18 saffron kernel: [39023.486039] usb-storage: Attempting
> to get CSW...
> Jun 17 19:21:18 saffron kernel: [39023.486042] usb-storage:
> usb_stor_bulk_transfer_buf: xfer 13 bytes
> Jun 17 19:21:18 saffron kernel: [39023.491787] usb-storage: Status
> code 0; transferred 13/13
> Jun 17 19:21:18 saffron kernel: [39023.491790] usb-storage: -- transfer
> complete Jun 17 19:21:18 saffron kernel: [39023.491793] usb-storage: Bulk
> status result = 0
> Jun 17 19:21:18 saffron kernel: [39023.491795] usb-storage: Bulk
> Status S 0x53425355 T 0x34ef R 0 Stat 0x0
> Jun 17 19:21:18 saffron kernel: [39023.491800] usb-storage:
> rts51x_invoke_transport: state:2
> Jun 17 19:21:18 saffron kernel: [39023.491802] usb-storage:
> rts51x_modi_suspend_timer: <---, state:2
> Jun 17 19:21:18 saffron kernel: [39023.491805] usb-storage:
> rts51x_modi_suspend_timer: --->
> Jun 17 19:21:18 saffron kernel: [39023.491807] usb-storage:
> rts51x_invoke_transport: --->
> Jun 17 19:21:18 saffron kernel: [39023.491809] usb-storage: scsi cmd
> done, result=0x0
> Jun 17 19:21:18 saffron kernel: [39023.491815] usb-storage: *** thread
> sleeping.
>
> ... Any idea what kernel configuration flag I may have enabled to
> cause these to be continually generated? My first guess would be
> something like 'kernel lock debugging'...if that's what I'm seeing
> here, where would I go to file a bug report against the usb-storage
> subsystem?

more like usb debugging options.


--
#163933

Alan McKinnon 06-18-2012 11:46 PM

Noisy dd operation
 
On Sun, 17 Jun 2012 21:03:35 -0400
Michael Mol <mikemol@gmail.com> wrote:

> > But what is your actual query? About the write speed?
>
> No, not really. TBH, I wasn't expecting to be able to consistently
> write quickly to the beginning of the card, but slowly at the end; I
> wanted to make sure the card wasn't going bad given the abruptness of
> the change. Actually, the more I think about it, I think it happened
> at the 2GB boundary, where some funky pin logic changes. (And where SD
> becomes SDHC). So I think that's where the performance shifted. Maybe
> I'll invest in a bunch of fast 2G cards, if it means the performance
> is consistent, and I'd still fit just under 200 shots.

I'm finding that SD and SDHC cards are not exactly reliable[1] when you
start write hammering them like they were spinning disks :-)

Remember early memory sticks and how 1000 writes was all you'd get from
some? Sort of like that. What prompted my response was I had just been
doing lots of writes and rewrites to my test cards for the Raspberry
Pi, and the latest one failed. Similar sort of nonsense message to what
you got, just from the mmc subsystem (I have a built-in card slot that
isn't USB). And that also happened somewhere near the 2G boundary
now that I figure the numbers back in my head.

[1] I'm talking of the cards regular folk can buy at the corner 'puter
shop, not the seriously high-quality ones that eg Dell ship with VMWare
servers. Those I believe are vastly superior (at a price)

--
Alan McKinnnon
alan.mckinnon@gmail.com


All times are GMT. The time now is 01:43 PM.

VBulletin, Copyright ©2000 - 2014, Jelsoft Enterprises Ltd.
Content Relevant URLs by vBSEO ©2007, Crawlability, Inc.