All of lore.kernel.org
 help / color / mirror / Atom feed
* dm-crypt low performance
@ 2009-01-12 19:22 Ritesh Raj Sarraf
       [not found] ` <0ths36-dce.ln1-b1aPebNLFEbkkoF7R9+BZ0EOCMrvLtNR@public.gmane.org>
  0 siblings, 1 reply; 10+ messages in thread
From: Ritesh Raj Sarraf @ 2009-01-12 19:22 UTC (permalink / raw)
  To: dm-devel; +Cc: dm-crypt

Hi,

I'm using dm-crypt on an external USB enclosure ide hdd. I copied 20Gb of 
data on to the encrypted device and am suffering severe performance penalty.
After a couple of seconds, all processes involved in the I/O keep stalling. 
They periodically resume, just for a couple of seconds and then again stall.

Running linux 2.6.26.


Here's the state of the Blocked Tasks during the stall.


[15869.848387] SysRq : Show Blocked State                                                                             
[15869.848387]   task                PC stack   pid father                                                            
[15869.848387] dolphin       D 00000040     0  5823      1                                                            
[15869.848387]        f29d5ce0 00000086 01c4e000 00000040 c03c1430 c03c4740 
c03c4740 f29d5ce0                         
[15869.848387]        f29d5e6c c2012740 00000000 4dd0acd3 00000e43 f79b48d0 
f29d5e6c 00000000                         
[15869.848387]        8f000000 c0135b72 02f7dbd6 f3033158 02f7dbd6 f2855d40 
c2012740 c2012b44                         
[15869.848387] Call Trace:                                                                                            
[15869.848387]  [<c0135b72>] getnstimeofday+0x32/0xaf                                                                 
[15869.848387]  [<c02c1091>] io_schedule+0x4f/0x86                                                                    
[15869.848387]  [<c01954ff>] sync_buffer+0x30/0x33                                                                    
[15869.848387]  [<c02c14fc>] __wait_on_bit+0x33/0x58                                                                  
[15869.848387]  [<c01954cf>] sync_buffer+0x0/0x33                                                                     
[15869.848387]  [<c02c15d7>] out_of_line_wait_on_bit+0xb6/0xbe                                                        
[15869.848387]  [<c01954cf>] sync_buffer+0x0/0x33                                                                     
[15869.848387]  [<c0131437>] wake_bit_function+0x0/0x3c                                                               
[15869.848387]  [<c019547f>] __wait_on_buffer+0x16/0x18                                                               
[15869.848387]  [<f8bae022>] ext3_find_entry+0x36b/0x4fb [ext3]                                                       
[15869.848387]  [<c01888e8>] ifind_fast+0x34/0x63                                                                     
[15869.848387]  [<c01893d1>] iget_locked+0x2a/0x105                                                                   
[15869.848387]  [<f8ba95e9>] ext3_iget+0xc/0x317 [ext3]                                                               
[15869.848387]  [<f8bae8be>] ext3_lookup+0x21/0x9b [ext3]                                                             
[15869.848387]  [<c017e590>] do_lookup+0xb4/0x153                                                                     
[15869.848387]  [<c01802bf>] __link_path_walk+0x834/0xc65                                                             
[15869.848387]  [<c018b72e>] mntput_no_expire+0x18/0xf0                                                               
[15869.848387]  [<c0187e3c>] dput+0x34/0xe4                                                                           
[15869.848387]  [<c018073b>] path_walk+0x4b/0x99                                                                      
[15869.848387]  [<c0180a10>] do_path_lookup+0x186/0x1cf                                                               
[15869.848387]  [<c017fa39>] getname+0x5e/0xb0                                                                        
[15869.848387]  [<c01812ee>] __user_walk_fd+0x29/0x3a                                                                 
[15869.848387]  [<c017b2c7>] vfs_stat_fd+0x15/0x3c                                                                    
[15869.848387]  [<c0127bef>] cap_set_effective+0x10/0x38                                                              
[15869.848387]  [<c01775a7>] sys_faccessat+0x143/0x14d                                                                
[15869.848387]  [<c017b3a3>] sys_stat64+0xf/0x24                                                                      
[15869.848387]  [<c015078a>] audit_syscall_entry+0xf8/0x122                                                           
[15869.848387]  [<c0108f3f>] do_syscall_trace+0x12a/0x16e                                                             
[15869.848387]  [<c010398a>] syscall_call+0x7/0xb                                                                     
[15869.848387]  [<c02c0000>] cpu_callback+0x4f/0x12a                                                                  
[15869.848387]  =======================                                                                               
[15869.848387] usb-storage   D c2012740     0 13131      2                                                            
[15869.848387]        f29d54a0 00000046 01c4e000 c2012740 c03c1430 c03c4740 
c03c4740 f29d54a0                         
[15869.848387]        f29d562c c2012740 00000000 d998eb08 f8a5b12f f29d54a0 
f29d562c 00eb4d09                         
[15869.848387]        f73b6600 f1a50708 00000000 00000000 00000000 000000ff 
f30453d8 7fffffff                         
[15869.848387] Call Trace:                                                                                            
[15869.848387]  [<f8a5b12f>] usb_hcd_submit_urb+0x766/0x82c [usbcore]                                                 
[15869.848387]  [<c02c12d5>] schedule_timeout+0x14/0xbb                                                               
[15869.848387]  [<c02c12d5>] schedule_timeout+0x14/0xbb                                                               
[15869.848387]  [<c01337e5>] enqueue_hrtimer+0xbd/0xc7                                                                
[15869.848387]  [<c010797b>] nommu_map_sg+0x78/0x86                                                                   
[15869.848387]  [<c02c11e8>] wait_for_common+0xbc/0x11a                                                               
[15869.848387]  [<c011a40d>] default_wake_function+0x0/0x8                                                            
[15869.848387]  [<f8a5bd38>] usb_sg_wait+0xfd/0x10a [usbcore]                                                         
[15869.848387]  [<f911af39>] usb_stor_bulk_transfer_sglist+0x72/0xb0 
[usb_storage]                                    
[15869.848387]  [<f911afe3>] usb_stor_bulk_srb+0x18/0x28 [usb_storage]                                                
[15869.848387]  [<f911b0f5>] usb_stor_Bulk_transport+0x102/0x23d 
[usb_storage]                                        
[15869.848387]  [<f911ad22>] usb_stor_invoke_transport+0x15/0x1ba 
[usb_storage]                                       
[15869.848387]  [<c0118140>] hrtick_start_fair+0xe1/0x126                                                             
[15869.848387]  [<c02c1aa1>] __down_interruptible+0x61/0x97                                                           
[15869.848387]  [<f911c080>] usb_stor_control_thread+0x113/0x1af 
[usb_storage]                                        
[15869.848387]  [<c011a8cc>] complete+0x28/0x36                                                                       
[15869.848387]  [<f911bf6d>] usb_stor_control_thread+0x0/0x1af [usb_storage]                                          
[15869.848387]  [<c01311a6>] kthread+0x38/0x5d                                                                        
[15869.848387]  [<c013116e>] kthread+0x0/0x5d                                                                         
[15869.848387]  [<c01045af>] kernel_thread_helper+0x7/0x10                                                            
[15869.848387]  =======================                                                                               
[15869.848387] kcryptd       D f7044a0c     0 13656      2                                                            
[15869.848387]        f29d79c0 00000046 01c58000 f7044a0c c03c1430 c03c4740 
c03c4740 f29d79c0                         
[15869.848387]        f29d7b4c c201c740 00000001 00010001 00000001 f79b48d0 
f29d7b4c 00eb4b70                         
[15869.848387]        c01df9a6 c0135b72 00000000 00000000 00000000 000000ff 
c201c740 c201cb44                         
[15869.848387] Call Trace:                                                                                            
[15869.848387]  [<c01df9a6>] cfq_may_queue+0x48/0xab                                                                  
[15869.848387]  [<c0135b72>] getnstimeofday+0x32/0xaf                                                                 
[15869.848387]  [<c02c1091>] io_schedule+0x4f/0x86                                                                    
[15869.848387]  [<c01d734f>] get_request_wait+0xf2/0x16d                                                              
[15869.848387]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
[15869.848387]  [<c01d7789>] __make_request+0x2b7/0x33a                                                               
[15869.848387]  [<c01d6465>] generic_make_request+0x419/0x44a                                                         
[15869.848387]  [<f8c30563>] async_encrypt+0x2f/0x35 [crypto_blkcipher]                                               
[15869.848387]  [<f8c659ce>] crypt_convert+0x20e/0x240 [dm_crypt]                                                     
[15869.848387]  [<f8c65c5d>] kcryptd_crypt+0x25d/0x339 [dm_crypt]                                                     
[15869.848387]  [<f8c65a00>] kcryptd_crypt+0x0/0x339 [dm_crypt]                                                       
[15869.848387]  [<f8c65a00>] kcryptd_crypt+0x0/0x339 [dm_crypt]                                                       
[15869.848387]  [<c012e818>] run_workqueue+0x73/0xed                                                                  
[15869.848387]  [<c012e949>] worker_thread+0xb7/0xc3                                                                  
[15869.848387]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
[15869.848387]  [<c012e892>] worker_thread+0x0/0xc3                                                                   
[15869.848387]  [<c01311a6>] kthread+0x38/0x5d                                                                        
[15869.848387]  [<c013116e>] kthread+0x0/0x5d                                                                         
[15869.848387]  [<c01045af>] kernel_thread_helper+0x7/0x10                                                            
[15869.848387]  =======================                                                                               
[15869.848387] kjournald     D 00000000     0 13832      2                                                            
[15869.848387]        f29d7180 00000046 01c4e000 00000000 c03c1430 c03c4740 
c03c4740 f29d7180                         
[15869.848387]        f29d730c c2012740 00000000 00000008 c0194792 f79b48d0 
f29d730c 00eab469                         
[15869.848387]        87000000 c0135b72 00000000 00000000 00000000 000000ff 
c2012740 c2012b44                         
[15869.848387] Call Trace:                                                                                            
[15869.848387]  [<c0194792>] __find_get_block_slow+0xdf/0xe8                                                          
[15869.848387]  [<c0135b72>] getnstimeofday+0x32/0xaf                                                                 
[15869.848387]  [<c02c1091>] io_schedule+0x4f/0x86                                                                    
[15869.848387]  [<c01954ff>] sync_buffer+0x30/0x33                                                                    
[15869.848387]  [<c02c14fc>] __wait_on_bit+0x33/0x58                                                                  
[15869.848387]  [<c01954cf>] sync_buffer+0x0/0x33                                                                     
[15869.848387]  [<c02c15d7>] out_of_line_wait_on_bit+0xb6/0xbe                                                        
[15869.848387]  [<c01954cf>] sync_buffer+0x0/0x33                                                                     
[15869.848387]  [<c0131437>] wake_bit_function+0x0/0x3c                                                               
[15869.848387]  [<c019547f>] __wait_on_buffer+0x16/0x18                                                               
[15869.848387]  [<c01958a3>] sync_dirty_buffer+0x6b/0x9c                                                              
[15869.848387]  [<f8b78fd5>] journal_commit_transaction+0x8b8/0xbc3 [jbd]                                             
[15869.848387]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
[15869.848387]  [<f8b7b5d5>] kjournald+0xb2/0x1cd [jbd]                                                               
[15869.848387]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
[15869.848387]  [<f8b7b523>] kjournald+0x0/0x1cd [jbd]                                                                
[15869.848387]  [<c01311a6>] kthread+0x38/0x5d                                                                        
[15869.848387]  [<c013116e>] kthread+0x0/0x5d                                                                         
[15869.848387]  [<c01045af>] kernel_thread_helper+0x7/0x10                                                            
[15869.848387]  =======================                                                                               
[15869.848387] kio_file      D c0135b72     0 14078   5348                                                            
[15869.848387]        f114d8c0 00000082 01c4e000 c0135b72 c03c1430 c03c4740 
c03c4740 f114d8c0                         
[15869.848387]        f114da4c c2012740 00000000 00000000 c0134170 f79b48d0 
f114da4c 00eab183                         
[15869.848387]        9e000000 c0135b72 00000000 00000000 00000000 000000ff 
c2012740 c2012b44                         
[15869.848387] Call Trace:                                                                                            
[15869.848387]  [<c0135b72>] getnstimeofday+0x32/0xaf                                                                 
[15869.848387]  [<c0134170>] ktime_get+0xf/0x2b                                                                       
[15869.848387]  [<c0135b72>] getnstimeofday+0x32/0xaf                                                                 
[15869.848387]  [<c02c1091>] io_schedule+0x4f/0x86                                                                    
[15869.848387]  [<c01954ff>] sync_buffer+0x30/0x33                                                                    
[15869.848387]  [<c02c14fc>] __wait_on_bit+0x33/0x58                                                                  
[15869.848387]  [<c01954cf>] sync_buffer+0x0/0x33                                                                     
[15869.848387]  [<c02c15d7>] out_of_line_wait_on_bit+0xb6/0xbe                                                        
[15869.848387]  [<c01954cf>] sync_buffer+0x0/0x33                                                                     
[15869.848387]  [<c0131437>] wake_bit_function+0x0/0x3c                                                               
[15869.848387]  [<c019547f>] __wait_on_buffer+0x16/0x18                                                               
[15869.848387]  [<c0195558>] bh_submit_read+0x47/0x56                                                                 
[15869.848387]  [<f8ba66e1>] read_block_bitmap+0x6a/0x115 [ext3]                                                      
[15869.848387]  [<f8ba732c>] ext3_new_blocks+0x253/0x569 [ext3]                                                       
[15869.848387]  [<f8baac45>] ext3_get_blocks_handle+0x332/0x785 [ext3]                                                
[15869.848387]  [<c0194ac9>] __find_get_block+0x162/0x16c                                                             
[15869.848387]  [<f8bab137>] ext3_get_block+0x9f/0xd3 [ext3]                                                          
[15869.848387]  [<c0195ef8>] __block_prepare_write+0x16e/0x373                                                        
[15869.848387]  [<c0196245>] block_write_begin+0x6c/0xc3                                                              
[15869.848387]  [<f8bab098>] ext3_get_block+0x0/0xd3 [ext3]                                                           
[15869.848387]  [<f8baa814>] ext3_write_begin+0xc1/0x168 [ext3]                                                       
[15869.848387]  [<f8bab098>] ext3_get_block+0x0/0xd3 [ext3]                                                           
[15869.848387]  [<c015912d>] generic_file_buffered_write+0xfa/0x56a                                                   
[15869.848387]  [<c01d0753>] cap_inode_need_killpriv+0x25/0x35                                                        
[15869.848387]  [<c01bdcd1>] security_inode_need_killpriv+0xc/0xd                                                     
[15869.848387]  [<c0159b98>] __generic_file_aio_write_nolock+0x3fa/0x445                                              
[15869.848387]  [<c0116c36>] kunmap_atomic+0x58/0x89                                                                  
[15869.848387]  [<c018acfa>] mnt_want_write+0x1a/0x5e                                                                 
[15869.848387]  [<c018b649>] mnt_drop_write+0x1a/0xb2                                                                 
[15869.848387]  [<c015a194>] generic_file_aio_read+0x474/0x4fa                                                        
[15869.848387]  [<c0159c43>] generic_file_aio_write+0x60/0xb7                                                         
[15869.848387]  [<f8ba7f6c>] ext3_file_write+0x19/0x85 [ext3]                                                         
[15869.848387]  [<c017815d>] do_sync_write+0xc0/0x107                                                                 
[15869.848387]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
[15869.848387]  [<c0104420>] apic_timer_interrupt+0x28/0x30                                                           
[15869.848387]  [<c017809d>] do_sync_write+0x0/0x107                                                                  
[15869.848387]  [<c01789d9>] vfs_write+0x84/0x121                                                                     
[15869.848387]  [<c0178b0e>] sys_write+0x3c/0x63                                                                      
[15869.848387]  [<c010398a>] syscall_call+0x7/0xb                                                                     
[15869.848387]  [<c02c0000>] cpu_callback+0x4f/0x12a                                                                  
[15869.848387]  =======================                                                                               
[15869.848387] pdflush       D ce29f9c0     0 14381      2                                                            
[15869.848387]        ce29d8c0 00000046 01c4e000 ce29f9c0 c03c1430 c03c4740 
c03c4740 ce29d8c0                         
[15869.848387]        ce29da4c c2012740 00000000 3c2642f9 00000004 00000286 
ce29da4c 00eb4d15                         
[15869.848387]        ce29daf9 d98ffef8 00000000 00000000 00000000 000000ff 
00eb4d78 00eb4d78                         
[15869.848387] Call Trace:                                                                                            
[15869.848387]  [<c02c1360>] schedule_timeout+0x9f/0xbb                                                               
[15869.848387]  [<c0128f95>] process_timeout+0x0/0x5                                                                  
[15869.848387]  [<c02c135b>] schedule_timeout+0x9a/0xbb                                                               
[15869.848387]  [<c02c08d1>] io_schedule_timeout+0x54/0x90                                                            
[15869.848387]  [<c0162769>] congestion_wait+0x51/0x66                                                                
[15869.848387]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
[15869.848387]  [<c015e135>] background_writeout+0x9e/0xa8                                                            
[15869.848387]  [<c015e6e5>] pdflush+0x128/0x1c4                                                                      
[15869.848387]  [<c015e097>] background_writeout+0x0/0xa8                                                             
[15869.848387]  [<c015e5bd>] pdflush+0x0/0x1c4                                                                        
[15869.848387]  [<c01311a6>] kthread+0x38/0x5d                                                                        
[15869.848387]  [<c013116e>] kthread+0x0/0x5d                                                                         
[15869.848387]  [<c01045af>] kernel_thread_helper+0x7/0x10                                                            
[15869.848387]  =======================                                                                               
[15869.848387] pdflush       D c03572f4     0 14393      2                                                            
[15869.848387]        ce29f9c0 00000046 01c4e000 c03572f4 c03c1430 c03c4740 
c03c4740 ce29f9c0                         
[15869.848387]        ce29fb4c c2012740 00000000 424a07a6 00000e4c 00000286 
ce29fb4c da55bf00                         
[15869.848387]        ce29fbf9 da55bf00 00000286 c0129430 00eb4d78 00000286 
00eb4d78 00eb4d78                         
[15869.848387] Call Trace:                                                                                            
[15869.848387]  [<c0129430>] __mod_timer+0xba/0xc3                                                                    
[15869.848387]  [<c02c1360>] schedule_timeout+0x9f/0xbb                                                               
[15869.848387]  [<c0128f95>] process_timeout+0x0/0x5                                                                  
[15869.848387]  [<c02c135b>] schedule_timeout+0x9a/0xbb                                                               
[15869.848387]  [<c02c08d1>] io_schedule_timeout+0x54/0x90                                                            
[15869.848387]  [<c0162769>] congestion_wait+0x51/0x66                                                                
[15869.848387]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
[15869.848387]  [<c015dca7>] wb_kupdate+0x98/0xe0                                                                     
[15869.848387]  [<c015e6e5>] pdflush+0x128/0x1c4                                                                      
[15869.848387]  [<c015dc0f>] wb_kupdate+0x0/0xe0                                                                      
[15869.848387]  [<c015e5bd>] pdflush+0x0/0x1c4                                                                        
[15869.848387]  [<c01311a6>] kthread+0x38/0x5d                                                                        
[15869.848387]  [<c013116e>] kthread+0x0/0x5d                                                                         
[15869.848387]  [<c01045af>] kernel_thread_helper+0x7/0x10                                                            
[15869.848387]  =======================                                                                               
[15869.848387] Sched Debug Version: v0.07, 2.6.26-custom #1                                                           
[15869.848387] now at 15720716.621199 msecs                                                                           
[15869.848387]   .sysctl_sched_latency                    : 40.000000                                                 
[15869.848387]   .sysctl_sched_min_granularity            : 8.000000                                                  
[15869.848387]   .sysctl_sched_wakeup_granularity         : 20.000000                                                 
[15869.848387]   .sysctl_sched_child_runs_first           : 0.000001                                                  
[15869.848387]   .sysctl_sched_features                   : 895                                                       
[15869.848387]                                                                                                        
[15869.848387] cpu#0, 1997.378 MHz                                                                                    
[15869.848387]   .nr_running                    : 0                                                                   
[15869.848387]   .load                          : 0                                                                   
[15869.848387]   .nr_switches                   : 24816086                                                            
[15869.848387]   .nr_load_updates               : 9274614                                                             
[15869.848387]   .nr_uninterruptible            : 4294964470                                                          
[15869.848387]   .jiffies                       : 15420709                                                            
[15869.848387]   .next_balance                  : 15.420961                                                           
[15869.848387]   .curr->pid                     : 0                                                                   
[15869.848387]   .clock                         : 15720716.023917                                                     
[15869.848387]   .cpu_load[0]                   : 0                                                                   
[15869.848387]   .cpu_load[1]                   : 108                                                                 
[15869.848387]   .cpu_load[2]                   : 433                                                                 
[15869.848387]   .cpu_load[3]                   : 493                                                                 
[15869.848387]   .cpu_load[4]                   : 359                                                                 
[15869.848387]                                                                                                        
[15869.848387] cfs_rq[0]:                                                                                             
[15869.848387]   .exec_clock                    : 0.000000                                                            
[15869.848387]   .MIN_vruntime                  : 0.000001                                                            
[15869.848387]   .min_vruntime                  : 2414306.866666                                                      
[15869.848387]   .max_vruntime                  : 0.000001                                                            
[15869.848387]   .spread                        : 0.000000                                                            
[15869.848387]   .spread0                       : 0.000000                                                            
[15869.848387]   .nr_running                    : 0                                                                   
[15869.848387]   .load                          : 0                                                                   
[15869.848387]   .nr_spread_over                : 0                                                                   
[15869.848387]                                                                                                        
[15869.848387] runnable tasks:                                                                                        
[15869.848387]             task   PID         tree-key  switches  prio     
exec-runtime         sum-exec        sum-sleep                                                                                                                   
[15869.848387] 
----------------------------------------------------------------------------------------------------------                                                                                                                   
[15869.848387]                                                                                                        
[15869.848387] cpu#1, 1997.378 MHz                                                                                    
[15869.848387]   .nr_running                    : 3                                                                   
[15869.848387]   .load                          : 3072                                                                
[15869.848387]   .nr_switches                   : 22671295                                                            
[15869.848387]   .nr_load_updates               : 10377709                                                            
[15869.848387]   .nr_uninterruptible            : 2833                                                                
[15869.848387]   .jiffies                       : 15420709                                                            
[15869.848387]   .next_balance                  : 15.420960                                                           
[15869.848387]   .curr->pid                     : 14604                                                               
[15869.848387]   .clock                         : 15720710.258267                                                     
[15869.848387]   .cpu_load[0]                   : 1024                                                                
[15869.848387]   .cpu_load[1]                   : 1008                                                                
[15869.848387]   .cpu_load[2]                   : 844                                                                 
[15869.848387]   .cpu_load[3]                   : 657                                                                 
[15869.848387]   .cpu_load[4]                   : 766                                                                 
[15869.848387]                                                                                                        
[15869.848387] cfs_rq[1]:                                                                                             
[15869.848387]   .exec_clock                    : 0.000000                                                            
[15869.848387]   .MIN_vruntime                  : 1992615.065627
[15869.848387]   .min_vruntime                  : 1992655.065624
[15869.848387]   .max_vruntime                  : 1992653.011804
[15869.848387]   .spread                        : 37.946177
[15869.848387]   .spread0                       : -421651.801042
[15869.848387]   .nr_running                    : 3
[15869.848387]   .load                          : 3072
[15869.848387]   .nr_spread_over                : 0
[15869.848387]
[15869.848387] runnable tasks:
[15869.848387]             task   PID         tree-key  switches  prio     
exec-runtime         sum-exec        sum-sleep
[15869.848387] 
----------------------------------------------------------------------------------------------------------
[15869.848387]         rsyslogd  3557   1992615.065627        97   120               
0               0               0.000000               0.000000               
0.000000 /
[15869.848387]              top 14469   1992653.011804       579   120               
0               0               0.000000               0.000000               
0.000000 /
[15869.848387] R           bash 14604   1992615.169510       173   120               
0               0               0.000000               0.000000               
0.000000 /
[15869.848387]


Ritesh
-- 
If possible, Please CC me when replying. I'm not subscribed to the list.

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [dm-devel] dm-crypt low performance
       [not found] ` <0ths36-dce.ln1-b1aPebNLFEbkkoF7R9+BZ0EOCMrvLtNR@public.gmane.org>
@ 2009-01-13 15:50   ` Milan Broz
  2009-01-13 17:37     ` Ritesh Raj Sarraf
  0 siblings, 1 reply; 10+ messages in thread
From: Milan Broz @ 2009-01-13 15:50 UTC (permalink / raw)
  To: Ritesh Raj Sarraf; +Cc: device-mapper development, dm-crypt-4q3lyFh4P1g

Ritesh Raj Sarraf wrote:
> I'm using dm-crypt on an external USB enclosure ide hdd. I copied 20Gb of 
> data on to the encrypted device and am suffering severe performance penalty.
> After a couple of seconds, all processes involved in the I/O keep stalling. 
> They periodically resume, just for a couple of seconds and then again stall.
> 
> Running linux 2.6.26.

Please can you try it without dm-crypt involved?
Just copy 20Gb to your unencrypted disk attached through USB.

I saw this problem with plain USB attached storage some time ago too.

There is only one thread in dm-crypt and it is waiting for io_schedule,
so I think it is not dm-crypt who is blocking it, but the layer
below the dm-crypt.

Milan

> [15869.848387] kcryptd       D f7044a0c     0 13656      2                                                            
> [15869.848387]        f29d79c0 00000046 01c58000 f7044a0c c03c1430 c03c4740 
> c03c4740 f29d79c0                         
> [15869.848387]        f29d7b4c c201c740 00000001 00010001 00000001 f79b48d0 
> f29d7b4c 00eb4b70                         
> [15869.848387]        c01df9a6 c0135b72 00000000 00000000 00000000 000000ff 
> c201c740 c201cb44                         
> [15869.848387] Call Trace:                                                                                            
> [15869.848387]  [<c01df9a6>] cfq_may_queue+0x48/0xab                                                                  
> [15869.848387]  [<c0135b72>] getnstimeofday+0x32/0xaf                                                                 
> [15869.848387]  [<c02c1091>] io_schedule+0x4f/0x86                                                                    
> [15869.848387]  [<c01d734f>] get_request_wait+0xf2/0x16d                                                              
> [15869.848387]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
> [15869.848387]  [<c01d7789>] __make_request+0x2b7/0x33a                                                               
> [15869.848387]  [<c01d6465>] generic_make_request+0x419/0x44a                                                         
> [15869.848387]  [<f8c30563>] async_encrypt+0x2f/0x35 [crypto_blkcipher]                                               
> [15869.848387]  [<f8c659ce>] crypt_convert+0x20e/0x240 [dm_crypt]                                                     
> [15869.848387]  [<f8c65c5d>] kcryptd_crypt+0x25d/0x339 [dm_crypt]                                                     
> [15869.848387]  [<f8c65a00>] kcryptd_crypt+0x0/0x339 [dm_crypt]                                                       
> [15869.848387]  [<f8c65a00>] kcryptd_crypt+0x0/0x339 [dm_crypt]                                                       
> [15869.848387]  [<c012e818>] run_workqueue+0x73/0xed                                                                  
> [15869.848387]  [<c012e949>] worker_thread+0xb7/0xc3                                                                  
> [15869.848387]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
> [15869.848387]  [<c012e892>] worker_thread+0x0/0xc3                                                                   
> [15869.848387]  [<c01311a6>] kthread+0x38/0x5d                                                                        
> [15869.848387]  [<c013116e>] kthread+0x0/0x5d                                                                         
> [15869.848387]  [<c01045af>] kernel_thread_helper+0x7/0x10                                                            

Milan
--
mbroz-H+wXaHxf7aLQT0dZR+AlfA@public.gmane.org

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: dm-crypt low performance
  2009-01-13 15:50   ` [dm-devel] " Milan Broz
@ 2009-01-13 17:37     ` Ritesh Raj Sarraf
  2009-01-13 19:52       ` Ritesh Raj Sarraf
  2009-01-13 19:52       ` Ritesh Raj Sarraf
  0 siblings, 2 replies; 10+ messages in thread
From: Ritesh Raj Sarraf @ 2009-01-13 17:37 UTC (permalink / raw)
  To: Milan Broz; +Cc: dm-crypt, device-mapper development


[-- Attachment #1.1: Type: text/plain, Size: 36660 bytes --]

On Tuesday 13 Jan 2009 21:20:48 Milan Broz wrote:
> Ritesh Raj Sarraf wrote:
> > I'm using dm-crypt on an external USB enclosure ide hdd. I copied 20Gb of
> > data on to the encrypted device and am suffering severe performance
> > penalty. After a couple of seconds, all processes involved in the I/O
> > keep stalling. They periodically resume, just for a couple of seconds and
> > then again stall.
> >
> > Running linux 2.6.26.
>
> Please can you try it without dm-crypt involved?
> Just copy 20Gb to your unencrypted disk attached through USB.
>
> I saw this problem with plain USB attached storage some time ago too.
>
> There is only one thread in dm-crypt and it is waiting for io_schedule,
> so I think it is not dm-crypt who is blocking it, but the layer
> below the dm-crypt.

So I tried the following.

Copied 20Gb of data to a partition on the External USB disk. Here are the 
results:

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
 11  10   0  79   0   1|  22M   39M|2864B 2454B|   0     0 |2048  3793 
 12   9   1  76   0   1|  23M   39M|  81k 8686B|   0     0 |2166  3635 
 13   8  16  62   0   1|  27M   43M|  12k 5036B|   0     0 |2127  3526 
 14   8  37  40   0   1|  24M   42M|7138B 5140B|   0     0 |2047  3415 
  7   8  47  36   0   0|  35M   40M|2451B 2538B|   0     0 |2002  3179 
  4   9  49  37   0   0|  41M   40M|4081B  276B|   0     0 |1974  2956 
  1   9  50  38   0   1|  40M   40M|   0   276B|   0     0 |1912  2774 
  1   8  50  39   0   1|  40M   40M|  92B    0 |   0     0 |2018  2958 
  2   9  48  39   0   0|  44M   40M| 362B  276B|   0     0 |2097  3191 
  8   8  45  38   0   1|  27M   33M|  23k 4181B|   0     0 |1919  3009
  8   8  50  34   0   0|  31M   26M|  10k 2570B|   0     0 |1760  2724
 21  11  33  30   0   3|  40M   40M| 204k   17k|   0     0 |2360  3845
 13   8  43  36   0   0|  35M   39M|  12k 5354B|   0     0 |2083  3349
 16   8  41  35   0   0|  30M   35M|5738B 4158B|   0     0 |1904  3118
  8  10  47  33   0   1|  40M   37M|1718B 1255B|   0     0 |1932  3130
  3   9  49  39   0   1|  40M   40M|   0     0 |   0     0 |2124  3065
  4   9  46  41   0   0|  40M   40M|   0     0 |   0     0 |1971  3088
  6   9  46  40   0   0|  40M   41M| 850B  723B|   0     0 |2059  3155
  3  10  46  39   0   1|  40M   42M|1958B 1651B|   0     0 |2054  3217
  8  12  41  38   0   1|  41M   39M|2741B 1342B|   0     0 |2083  3647
  4   8  47  40   0   0|  39M   39M|2062B 1299B|   0     0 |2060  3328

Looks good.

Then I tried copying 20Gb of data to the dm-crypted partition on the same USB 
disk. Here are the results:

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  3  28   0  67   0   1|  20M   41M|   0     0 |   0     0 |1972  3036
 25  29   0  44   0   2|  39M   42M|   0    78B|  52k    0 |1800  3612
 41  22   0  35   0   1|8952k   40M|  54B   65B|   0     0 |1493  3471
 21  24   0  54   0   1|2040k   42M|1469B 1591B|   0     0 |2180  5170
 16  24   0  59   0   1|  14M   44M|  25k 4962B|   0     0 |1991  4541
 12  11  17  58   0   2|  36M   19M|  28k 2964B|  44k    0 |2351  3774
 19  28  14  37   0   1|  40M   19M|  72k 5062B|   0     0 |1707  3906
 14  29   0  54   0   3|  58M   42M| 108k 7586B|   0     0 |2431  4646
  8  23   0  67   0   2|  44M   35M|  77k 4188B|   0     0 |2948  4587
 22  19   6  50   0   1|  30M   38M|  41k 2666B|   0     0 |2127  3924
  6  33  29  31   0   1|  52M   38M|7628B 1511B|   0     0 |2055  3375
  4  25   0  70   0   1|4624k   39M|4447B 1429B|   0     0 |1808  2749
 10  32   3  52   1   2|  53M   42M|  27k 2296B|   0     0 |2144  4474
  5  17   0  77   0   1|  88k   38M|5515B  420B|   0     0 |2261  3338
  6  24   1  67   0   1|  66M   37M|   0     0 |   0     0 |2741  4099
  2  27  17  53   0   1|  64M   32M|   0     0 |  32k    0 |2331  3356
  2  35  17  43   0   2|  71M   39M|   0     0 |   0     0 |2460  3713
  3  33   5  57   0   2|  69M   40M| 189B  202B|   0     0 |2212  3366
  1  36   0  61   0   1|  72M   42M|   0     0 |   0     0 |2296  3481
  1  35   0  62   0   2|  69M   40M|   0    65B|   0     0 |2235  3425
  2  24   0  73   0   1|  37M   39M|   0     0 |   0     0 |2033  2912 ^C

The above 2 results are from a 2.5" SATA disk attached to a USB 2.0 enclosure 
which has one USB connector connected to the laptop's USB port. This is a 
self-powered disk enclosure. Filesystems is use were, vfat for the former 
result and ext3 for the latter.

Below are results from a different disk.

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--  
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw   
 10  17  26  44   0   2|  32M   35M|   0     0 |   0     0 |3889    18k
 12  20  34  35   0   0|  34M   36M|   0     0 |   0     0 |3923    19k
 14  20  21  42   0   1|  36M   36M|   0   648B|   0     0 |4036    20k
 14  22  21  41   0   0|  45M   37M|   0   324B|   0     0 |4140    24k
 15  21  10  52   0   2|  35M   35M| 448B  520B|   0     0 |3947    19k
 10  19  31  40   0   0|  30M   35M|   0     0 |   0     0 |3885    17k
 18  22  14  46   0   0|  36M   37M|  92B    0 |   0     0 |4029    21k
 16  21  18  43   0   1|  40M   36M|  92B    0 |   0     0 |3966    21k
 11  23  28  37   0   0|  37M   36M|  92B    0 |   0     0 |3986    20k
 11  17  31  41   0   0|  30M   35M|   0     0 |   0     0 |3893    19k
 12  19   6  62   0   1|  29M   34M|   0     0 |   0     0 |3895    18k
 12  19   0  67   0   2|  29M   35M|   0     0 |   0     0 |3974    17k
 17  15   0  66   0   1|  15M   33M|   0     0 |   0     0 |3802    11k
 32  17   5  46   0   0|  27M   36M| 108B  357B|   0     0 |3943    14k
 17  14   2  65   0   1|  14M   33M|   0     0 |   0     0 |3884    11k
 21  20  17  40   0   2|  28M   35M|   0     0 |   0     0 |3916    17k
 17  24   8  50   0   0|  40M   37M|  55B   96B|   0     0 |3982    22k
 19  27  13  41   0   0|  52M   37M|   0     0 |   0     0 |4265    29k
 20  25  13  42   0   0|  40M   36M|   0     0 |   0     0 |3979    22k
 21  28   8  41   1   2|  52M   36M| 420B  520B|   0     0 |4082    27k
 20  32  16  31   0   0|  68M   38M|   0     0 |   0     0 |4343    33k^C

This result is from a 2.5" SATA disk connected to a USB 2.0 enclosure with 2 
USB connectors connected to the laptop. The filesystem is fuse (ntfs-3g).
Looks good.


Here's the interesting one.

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
 11   3  82   2   0   1|1655k  267k|   0     0 |5486B   12k|1259  1863
 16  23  25  35   0   0|1360k    0 |3022B  336B|  32k    0 | 972  3043
  2  44  15  40   0   0|  64k    0 |   0     0 |   0     0 | 902  1141
  4   3  93   0   0   0|   0     0 |   0     0 |   0     0 | 769  1235
  5   2  92   0   0   0|   0   368k| 426B  520B|   0     0 | 557  1100
  4   3  93   0   0   0|   0     0 |  92B    0 |   0     0 | 506  1041
  4   3  94   0   0   0|   0     0 |   0     0 |   0     0 | 628  1005
  4   2  93   0   0   0|   0     0 |   0     0 |   0     0 | 547  1036
  6   2  92   0   0   0|   0     0 |   0     0 |   0     0 | 574   995
  4   2  94   0   0   0|   0     0 |   0     0 |   0     0 | 593  1126
  6   3  91   0   0   0|   0     0 | 141B   84B|   0     0 | 684  1165
  4   3  93   0   0   0|   0     0 |   0     0 |   0     0 | 514  1044
  4   2  93   0   0   0|   0     0 |   0     0 |   0     0 | 485   850
  4   3  92   0   0   0|   0     0 | 227B  484B|   0     0 | 645  1116
  3   2  94   0   0   0|   0     0 |   0     0 |   0     0 | 619  1009
  4   3  92   1   0   0|8192B 1472k| 108B  292B|   0     0 | 608  1072
  5   3  92   0   0   0|   0     0 | 187B   72B|   0     0 | 786  1208
  4   2  94   0   0   0|   0     0 |   0     0 |   0     0 | 587  1098
  3   3  94   0   0   0|   0     0 |   0     0 |   0     0 | 500   939 ^C


This result is from a *3.5"* ATA disk connected to a USB 2.0 enclosure with 2 
USB connectors connected to the laptop. The enclosure is externally powered. 
The disk is partition-less. The entire disk (/dev/sdb) is LUKS encrypted.
The filesystem is ext3.

As soon as I initiated the I/O, the performance went down (as mentioned in the 
above result). Also, the usb port was reset immediately which resulted in a 
read-only filesystem.

Here are the relevant logs.

[44125.008940] usb 5-8: new high speed USB device using ehci_hcd and address 
10                                       
[44125.375160] usb 4-2: new full speed USB device using uhci_hcd and address 2                                        
[44125.488926] usb 4-2: device descriptor read/64, error -71                                                          
[44125.717839] usb 4-2: not running at top speed; connect to a high speed hub                                         
[44125.732838] usb 4-2: configuration #1 chosen from 1 choice                                                         
[44125.735518] scsi5 : SCSI emulation for USB Mass Storage devices                                                    
[44125.736912] usb 4-2: New USB device found, idVendor=05e3, idProduct=0702                                           
[44125.736928] usb 4-2: New USB device strings: Mfr=0, Product=1, 
SerialNumber=0                                      
[44125.736933] usb 4-2: Product: USB TO IDE                                                                           
[44125.737807] usb-storage: device found at 2                                                                         
[44125.737814] usb-storage: waiting for device to settle before scanning                                              
[44130.771126] usb-storage: device scan complete                                                                      
[44130.774592] scsi 5:0:0:0: Direct-Access     ST325082 4A               0811 
PQ: 0 ANSI: 0                           
[44130.780522] sd 5:0:0:0: [sdb] 488397168 512-byte hardware sectors (250059 
MB)                                      
[44130.787520] sd 5:0:0:0: [sdb] Test WP failed, assume Write Enabled                                                 
[44130.787520] sd 5:0:0:0: [sdb] Assuming drive cache: write through                                                  
[44130.792520] sd 5:0:0:0: [sdb] 488397168 512-byte hardware sectors (250059 
MB)                                      
[44130.799520] sd 5:0:0:0: [sdb] Test WP failed, assume Write Enabled                                                 
[44130.799520] sd 5:0:0:0: [sdb] Assuming drive cache: write through                                                  
[44130.799520]  sdb: unknown partition table                                                                          
[44130.830056] sd 5:0:0:0: [sdb] Attached SCSI disk                                                                   
[44130.830056] sd 5:0:0:0: Attached scsi generic sg2 type 0                                                           
[44273.057272] kjournald starting.  Commit interval 5 seconds                                                         
[44273.064954] EXT3 FS on dm-2, internal journal                                                                      
[44273.065232] EXT3-fs: mounted filesystem with ordered data mode.                                                    
[44306.991719] usb 4-2: reset full speed USB device using uhci_hcd and address 
2                                      
[44307.232054] usb 4-2: reset full speed USB device using uhci_hcd and address 
2                                      
[44307.468171] usb 4-2: reset full speed USB device using uhci_hcd and address 
2                                      
[44307.600787] usb 4-2: failed to restore interface 0 altsetting 0 (error=-71)                                        
[44307.601609] usb 4-2: USB disconnect, address 2                                                                     
[44307.601609] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR 
driverbyte=DRIVER_OK,SUGGEST_OK                           
[44307.601609] end_request: I/O error, dev sdb, sector 248121664                                                      
[44307.601609] Buffer I/O error on device dm-2, logical block 31015079                                                
[44307.601609] lost page write due to I/O error on dm-2                                                               
[44307.601609] Buffer I/O error on device dm-2, logical block 31015080                                                
[44307.601609] lost page write due to I/O error on dm-2                                                               
[44307.601609] Buffer I/O error on device dm-2, logical block 31015081                                                
[44307.601609] lost page write due to I/O error on dm-2                                                               
[44307.601609] Buffer I/O error on device dm-2, logical block 31015082                                                
[44307.601609] lost page write due to I/O error on dm-2                                                               
[44307.601635] Buffer I/O error on device dm-2, logical block 31015083                                                
[44307.601639] lost page write due to I/O error on dm-2                                                               
[44307.601648] Buffer I/O error on device dm-2, logical block 31015084                                                
[44307.602572] lost page write due to I/O error on dm-2                                                               
[44307.602572] Buffer I/O error on device dm-2, logical block 31015085                                                
[44307.602572] lost page write due to I/O error on dm-2                                                               
[44307.602572] Buffer I/O error on device dm-2, logical block 31015086                                                
[44307.602572] lost page write due to I/O error on dm-2                                                               
[44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR 
driverbyte=DRIVER_OK,SUGGEST_OK                           
[44307.602572] end_request: I/O error, dev sdb, sector 248121728                                                      
[44307.602572] Buffer I/O error on device dm-2, logical block 31015087                                                
[44307.602572] lost page write due to I/O error on dm-2                                                               
[44307.602572] Buffer I/O error on device dm-2, logical block 31015088                                                
[44307.602572] lost page write due to I/O error on dm-2                                                               
[44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR 
driverbyte=DRIVER_OK,SUGGEST_OK                           
[44307.602572] end_request: I/O error, dev sdb, sector 248121792                                                      
[44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR 
driverbyte=DRIVER_OK,SUGGEST_OK                           
[44307.602572] end_request: I/O error, dev sdb, sector 248121856                                                      
[44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR 
driverbyte=DRIVER_OK,SUGGEST_OK                           
[44307.602572] end_request: I/O error, dev sdb, sector 248121920                                                      
[44307.602573] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR 
driverbyte=DRIVER_OK,SUGGEST_OK                           
[44307.602573] end_request: I/O error, dev sdb, sector 248121984                                                      
[44307.603601] sd 5:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT 
driverbyte=DRIVER_OK,SUGGEST_OK                      
[44307.603609] end_request: I/O error, dev sdb, sector 248122048                                                      
[44307.604568] sd 5:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT 
driverbyte=DRIVER_OK,SUGGEST_OK                      
[44307.604568] end_request: I/O error, dev sdb, sector 248122112                                                      
[44307.625509] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44307.763898] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44307.763898] ------------[ cut here ]------------                                                                   
[44307.763898] WARNING: at fs/buffer.c:1186 mark_buffer_dirty+0x20/0x67()                                             
[44307.763898] Modules linked in: sha256_generic aes_i586 aes_generic cbc 
nls_utf8 nls_cp437 vfat fat nls_base usb_storage usbhid hid ff_memless tcp_diag 
inet_diag tun nvidia(P) rfcomm l2cap bluetooth xt_limit nf_conntrack_ipv6 ipv6 
nf_conntrack_proto_dccp ts_kmp nf_conntrack_amanda nf_conntrack_irc 
nf_conntrack_sip nf_conntrack_netbios_ns nf_conntrack_pptp 
nf_conntrack_proto_gre nf_conntrack_netlink nfnetlink nf_conntrack_ftp 
nf_conntrack_tftp nf_conntrack_sane xt_conntrack nf_conntrack_proto_sctp 
nf_conntrack_proto_udplite nf_conntrack_h323 acpi_cpufreq cpufreq_conservative 
cpufreq_stats cpufreq_userspace cpufreq_powersave ipt_MASQUERADE iptable_nat 
nf_nat nf_conntrack_ipv4 xt_state nf_conntrack ipt_REJECT xt_tcpudp 
iptable_filter ip_tables x_tables bridge kvm_intel kvm fuse configfs loop 
firewire_sbp2 dm_crypt snd_hda_intel snd_usb_audio snd_pcm_oss snd_mixer_oss 
snd_pcm snd_usb_lib snd_hwdep arc4 snd_seq_dummy ecb crypto_blkcipher 
snd_seq_oss snd_seq_midi snd_rawmidi uvcvideo iwl3945 snd_seq_midi_event 
compat_ioctl32 snd_seq joydev mac80211 videodev i2c_i801 snd_timer 
snd_seq_device iTCO_wdt led_class serio_raw snd v4l1_compat intel_agp wmi 
rng_core i2c_core ac cfg80211 psmouse pcspkr agpgart button battery video 
output soundcore snd_page_alloc evdev dcdbas ext3 jbd mbcache dm_mirror dm_log 
dm_snapshot dm_mod sg sr_mod cdrom sd_mod ata_generic ata_piix firewire_ohci 
firewire_core libata scsi_mod crc_itu_t dock b44 ide_pci_generic ide_core 
ohci1394 sdhci ieee1394 mmc_core ricoh_mmc ssb pcmcia pcmcia_core 
firmware_class mii ehci_hcd uhci_hcd usbcore thermal processor fan thermal_sys                                         
[44307.763898] Pid: 8632, comm: cp Tainted: P          2.6.26-custom #1                                               
[44307.763921]  [<c01219c0>] warn_on_slowpath+0x40/0x79                                                               
[44307.763921]  [<c0119aee>] check_preempt_wakeup+0x97/0xd1                                                           
[44307.763921]  [<c011a404>] try_to_wake_up+0xe8/0xf1                                                                 
[44307.763922]  [<c023397e>] vt_console_print+0x32/0x278                                                              
[44307.763922]  [<c023397e>] vt_console_print+0x32/0x278                                                              
[44307.763922]  [<c023394c>] vt_console_print+0x0/0x278                                                               
[44307.763937]  [<c0121c56>] __call_console_drivers+0x4f/0x5b                                                         
[44307.763950]  [<c013484a>] up+0x9/0x2a                                                                              
[44307.763969]  [<c0122066>] release_console_sem+0x172/0x18b                                                          
[44307.764087]  [<c0194ed5>] mark_buffer_dirty+0x20/0x67                                                              
[44307.764102]  [<f8b9dccb>] ext3_commit_super+0x3a/0x4e [ext3]                                                       
[44307.764147]  [<f8b9f0e2>] ext3_handle_error+0x6e/0x8e [ext3]                                                       
[44307.764178]  [<f8b9f18d>] ext3_error+0x3a/0x40 [ext3]                                                              
[44307.764237]  [<f8b94707>] read_block_bitmap+0x90/0x115 [ext3]                                                      
[44307.764307]  [<f8b95272>] ext3_new_blocks+0x199/0x569 [ext3]                                                       
[44307.764395]  [<f8b98c45>] ext3_get_blocks_handle+0x332/0x785 [ext3]                                                
[44307.764395]  [<c0194ac9>] __find_get_block+0x162/0x16c                                                             
[44307.764395]  [<c015bad2>] __rmqueue+0x16/0x1b5                                                                     
[44307.764395]  [<f8b99137>] ext3_get_block+0x9f/0xd3 [ext3]                                                          
[44307.764469]  [<c0195ef8>] __block_prepare_write+0x16e/0x373                                                        
[44307.764469]  [<c0196245>] block_write_begin+0x6c/0xc3                                                              
[44307.764469]  [<f8b99098>] ext3_get_block+0x0/0xd3 [ext3]                                                           
[44307.764469]  [<f8b98814>] ext3_write_begin+0xc1/0x168 [ext3]                                                       
[44307.764487]  [<f8b99098>] ext3_get_block+0x0/0xd3 [ext3]                                                           
[44307.764896]  [<c015912d>] generic_file_buffered_write+0xfa/0x56a                                                   
[44307.764997]  [<f8b11925>] journal_stop+0x145/0x14e [jbd]                                                           
[44307.765065]  [<c0159b98>] __generic_file_aio_write_nolock+0x3fa/0x445                                              
[44307.765141]  [<c018acfa>] mnt_want_write+0x1a/0x5e                                                                 
[44307.765157]  [<c018b649>] mnt_drop_write+0x1a/0xb2                                                                 
[44307.765172]  [<c015a194>] generic_file_aio_read+0x474/0x4fa                                                        
[44307.765203]  [<c0159c43>] generic_file_aio_write+0x60/0xb7                                                         
[44307.765253]  [<f8b95f6c>] ext3_file_write+0x19/0x85 [ext3]                                                         
[44307.765289]  [<c017815d>] do_sync_write+0xc0/0x107                                                                 
[44307.765369]  [<c013140a>] autoremove_wake_function+0x0/0x2d                                                        
[44307.765394]  [<c011e114>] hrtick_set+0x7b/0xe6                                                                     
[44307.765455]  [<c017809d>] do_sync_write+0x0/0x107                                                                  
[44307.765469]  [<c01789d9>] vfs_write+0x84/0x121                                                                     
[44307.765495]  [<c0178b0e>] sys_write+0x3c/0x63                                                                      
[44307.765525]  [<c010398a>] syscall_call+0x7/0xb                                                                     
[44307.765894]  =======================                                                                               
[44307.765894] ---[ end trace 2a0ce193654d04fb ]---                                                                   
[44307.884076] usb 4-2: new full speed USB device using uhci_hcd and address 3                                        
[44308.017388] usb 4-2: device descriptor read/all, error -71                                                         
[44308.026550] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.047000] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.056026] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.075044] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.090090] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.102860] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.117901] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.122647] usb 4-2: new full speed USB device using uhci_hcd and address 4                                        
[44308.127745] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.136581] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.150331] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.159068] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.168617] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.185580] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.200611] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.204343] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.217310] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.228915] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.254557] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.270601] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.300419] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.301453] usb 4-2: string descriptor 0 read error: -71                                                           
[44308.301572] usb 4-2: configuration #1 chosen from 1 choice                                                         
[44308.308850] usb 4-2: can't set config #1, error -71                                                                
[44308.308899] usb 4-2: New USB device found, idVendor=05e3, idProduct=0702                                           
[44308.308899] usb 4-2: New USB device strings: Mfr=0, Product=1, 
SerialNumber=0                                      
[44308.328418] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.336523] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.367727] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.384314] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.399502] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.423943] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.439201] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.450486] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.460527] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.464059] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.477362] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.498686] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.516538] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.520738] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.540687] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.557256] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.579235] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.590239] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.605335] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.628031] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44308.990689] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read 
block bitmap - block_group = 966, block_bitmap = 31653888                                                                                                        
[44309.667656] Aborting journal on device dm-2.                                                                       
[44309.668659] __journal_remove_journal_head: freeing b_committed_data                                                
[44309.668659] __journal_remove_journal_head: freeing b_frozen_data                                                   
[44309.668659] __journal_remove_journal_head: freeing b_frozen_data
[44309.668659] __journal_remove_journal_head: freeing b_frozen_data
[44309.668659] __journal_remove_journal_head: freeing b_frozen_data
[44309.668659] __journal_remove_journal_head: freeing b_frozen_data
[44309.668659] __journal_remove_journal_head: freeing b_frozen_data
[44309.679137] ext3_abort called.
[44309.679137] EXT3-fs error (device dm-2): ext3_journal_start_sb: Detected 
aborted journal
[44309.679137] Remounting filesystem read-only
[44338.161517] __ratelimit: 26116 messages suppressed
[44338.161517] Buffer I/O error on device dm-2, logical block 8
[44338.161517] lost page write due to I/O error on dm-2
[44338.161517] Buffer I/O error on device dm-2, logical block 1027
[44338.161517] lost page write due to I/O error on dm-2
[44338.161517] Buffer I/O error on device dm-2, logical block 1539
[44338.161517] lost page write due to I/O error on dm-2
[44338.161531] Buffer I/O error on device dm-2, logical block 30998528
[44338.161538] lost page write due to I/O error on dm-2
[44338.162759] Buffer I/O error on device dm-2, logical block 30998529
[44338.162767] lost page write due to I/O error on dm-2
[44338.162776] Buffer I/O error on device dm-2, logical block 30998530
[44338.162781] lost page write due to I/O error on dm-2


This makes me feel that it might be a hardware issue.

Ritesh
-- 
Ritesh Raj Sarraf
RESEARCHUT - http://www.researchut.com
"Necessity is the mother of invention."


[-- Attachment #1.2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 197 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]



^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: dm-crypt low performance
  2009-01-13 17:37     ` Ritesh Raj Sarraf
@ 2009-01-13 19:52       ` Ritesh Raj Sarraf
  2009-01-13 20:00         ` [linux-pm] " Alan Stern
  2009-01-13 20:00         ` Alan Stern
  2009-01-13 19:52       ` Ritesh Raj Sarraf
  1 sibling, 2 replies; 10+ messages in thread
From: Ritesh Raj Sarraf @ 2009-01-13 19:52 UTC (permalink / raw)
  To: Milan Broz; +Cc: rjw, device-mapper development, linux-pm


[-- Attachment #1.1: Type: text/plain, Size: 31650 bytes --]

Okay!! I think I now have the correct steps to reproduce it consistently.

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--  
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw   
 10  25   0  64   0   1| 128k   15M| 158B    0 |   0     0 |3475  6007
 10  35   0  53   0   2|  75M   15M|   0     0 |   0     0 |3741  6414
  9  35   7  47   0   1|  74M   15M|   0     0 |   0     0 |3798  6372
  9  36   3  50   0   2|  72M   13M|   0     0 |   0     0 |3476  5915
  9  28   0  62   0   1|  31M   14M|   0     0 |   0     0 |3455  5850
 10  23   0  65   0   1|   0    14M|  92B    0 |   0     0 |3103  5343
  3  21   0  75   0   1|   0    13M|  92B    0 |   0     0 |3056  4698
  2  21   0  76   0   1|   0    14M|  92B    0 |   0     0 |3121  4699
  3  20   0  76   0   1|   0    13M|   0     0 |   0     0 |2973  4487
  1  20   0  78   0   1|   0    13M|   0    65B|   0     0 |2991  4487
  4  22   0  72   0   1|  15M   13M|   0     0 |   0     0 |3147  4881
 10  21   5  63   0   1|  70M 3084k|   0     0 |   0     0 |2658  4568
  9  32  11  46   0   1|  72M 9848k|   0     0 |   0     0 |3192  5481
 10  37   0  51   0   2|  74M   17M|   0     0 |   0     0 |4042  6892
 10  28   0  61   0   1|  23M   16M|   0     0 |   0     0 |3619  6116
  2  26   0  71   0   1|   0    17M|   0     0 |   0     0 |3748  5736
  5  29   2  63   0   1|  34M   16M|   0     0 |   0     0 |3763  6144
  4  34   4  56   0   2|  40M   17M|   0     0 |   0     0 |3895  6392
  7  34   0  58   0   2|  44M   18M|   0     0 |   0     0 |3993  6056
 15  31   0  51   1   1|  50M   18M|   0    65B|   0  4096B|3816  7130
  1  37   0  60   0   2|  72M   17M|   0     0 |   0     0 |4079  6412 ^C

The above result is from a freshly booted linux with the same suspected faulty 
USB HDD enclosure. I ran it on 2 kernels, one standard and one debug, and both 
gave similar results.
So shouldn't be faulty hardware.


So then with my standard kernel, I booted + hibernated and then resumed and 
then again ran the I/O. Here are the same results.

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  1   1   0  97   0   0|   0   896k|  54B    0 |   0     0 | 666   778 
  2   2   0  95   0   0|   0   864k|  54B   78B|   0     0 | 693   834 
  1   1   0  98   0   0|   0   864k|   0     0 |   0     0 | 649   691 
  1   1   0  98   0   0|   0   896k|   0     0 |   0     0 | 655   727 
  2   2   0  96   0   0|   0  1112k|   0     0 |   0     0 | 700   854 
  2   1   0  97   0   0|   0  1032k|   0     0 |   0     0 | 669   865 
  2   1   0  96   0   0|   0  1048k|   0     0 |   0     0 | 650   816 
  2   2   0  97   0   0|   0   896k|   0     0 |   0     0 | 663   808 
  0   2   0  98   0   0|   0   864k|   0     0 |   0     0 | 635   686 
  3  13   0  82   0   0|  59M  928k|   0     0 |   0     0 |1326  1393 
  1  13   0  86   0   0|  74M  896k|   0     0 |   0     0 |1472  1388 
  2   8   0  90   0   0|  40M  928k|   0     0 |   0     0 |1163  1195 
  1   1   0  97   0   0|   0   864k|   0     0 |   0     0 | 738   829 
  2   2   0  96   0   0|   0   896k|   0     0 |   0     0 | 787   902 
  1   2   0  97   0   0|   0  1048k|   0     0 |   0     0 | 766   911 
  1   1   0  97   0   0|   0   896k|  92B    0 |   0     0 | 766   927 
  2   2  30  66   0   0|   0  1080k|  92B    0 |   0     0 | 750   868 
  1   1  51  47   0   0|   0   864k|  92B    0 |   0     0 | 712   808 
  1   1  50  47   0   0|   0   896k|  92B    0 |   0     0 | 722   872 
  1   2  10  86   0   0|   0   864k| 184B    0 |   0     0 | 748   972 
  1   1   0  98   0   0|   0   864k|  92B    0 |   0     0 | 730   817 

So this seems to be happening on my laptop when the OS has used the 
hibernation feature. I'm of-course doing a luksClose and USB device 
disconnection before hibernation.

Here's the usb device listing after hibernation/resume.

rrs@learner:~$ cat /tmp/lsusb.suspend
Bus 005 Device 005: ID 046d:08c6 Logitech, Inc. QuickCam for DELL Notebooks
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 007: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 005: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub


And here's the usb device listing after a fresh boot.

rrs@learner:~$ lsusb
Bus 005 Device 004: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
Bus 005 Device 003: ID 046d:08c6 Logitech, Inc. QuickCam for DELL Notebooks
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 004: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub


Ritesh




On Tuesday 13 Jan 2009 23:07:45 Ritesh Raj Sarraf wrote:
> On Tuesday 13 Jan 2009 21:20:48 Milan Broz wrote:
> > Ritesh Raj Sarraf wrote:
> > > I'm using dm-crypt on an external USB enclosure ide hdd. I copied 20Gb
> > > of data on to the encrypted device and am suffering severe performance
> > > penalty. After a couple of seconds, all processes involved in the I/O
> > > keep stalling. They periodically resume, just for a couple of seconds
> > > and then again stall.
> > >
> > > Running linux 2.6.26.
> >
> > Please can you try it without dm-crypt involved?
> > Just copy 20Gb to your unencrypted disk attached through USB.
> >
> > I saw this problem with plain USB attached storage some time ago too.
> >
> > There is only one thread in dm-crypt and it is waiting for io_schedule,
> > so I think it is not dm-crypt who is blocking it, but the layer
> > below the dm-crypt.
>
> So I tried the following.
>
> Copied 20Gb of data to a partition on the External USB disk. Here are the
> results:
>
> ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
>  11  10   0  79   0   1|  22M   39M|2864B 2454B|   0     0 |2048  3793
>  12   9   1  76   0   1|  23M   39M|  81k 8686B|   0     0 |2166  3635
>  13   8  16  62   0   1|  27M   43M|  12k 5036B|   0     0 |2127  3526
>  14   8  37  40   0   1|  24M   42M|7138B 5140B|   0     0 |2047  3415
>   7   8  47  36   0   0|  35M   40M|2451B 2538B|   0     0 |2002  3179
>   4   9  49  37   0   0|  41M   40M|4081B  276B|   0     0 |1974  2956
>   1   9  50  38   0   1|  40M   40M|   0   276B|   0     0 |1912  2774
>   1   8  50  39   0   1|  40M   40M|  92B    0 |   0     0 |2018  2958
>   2   9  48  39   0   0|  44M   40M| 362B  276B|   0     0 |2097  3191
>   8   8  45  38   0   1|  27M   33M|  23k 4181B|   0     0 |1919  3009
>   8   8  50  34   0   0|  31M   26M|  10k 2570B|   0     0 |1760  2724
>  21  11  33  30   0   3|  40M   40M| 204k   17k|   0     0 |2360  3845
>  13   8  43  36   0   0|  35M   39M|  12k 5354B|   0     0 |2083  3349
>  16   8  41  35   0   0|  30M   35M|5738B 4158B|   0     0 |1904  3118
>   8  10  47  33   0   1|  40M   37M|1718B 1255B|   0     0 |1932  3130
>   3   9  49  39   0   1|  40M   40M|   0     0 |   0     0 |2124  3065
>   4   9  46  41   0   0|  40M   40M|   0     0 |   0     0 |1971  3088
>   6   9  46  40   0   0|  40M   41M| 850B  723B|   0     0 |2059  3155
>   3  10  46  39   0   1|  40M   42M|1958B 1651B|   0     0 |2054  3217
>   8  12  41  38   0   1|  41M   39M|2741B 1342B|   0     0 |2083  3647
>   4   8  47  40   0   0|  39M   39M|2062B 1299B|   0     0 |2060  3328
>
> Looks good.
>
> Then I tried copying 20Gb of data to the dm-crypted partition on the same
> USB disk. Here are the results:
>
> ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
>   3  28   0  67   0   1|  20M   41M|   0     0 |   0     0 |1972  3036
>  25  29   0  44   0   2|  39M   42M|   0    78B|  52k    0 |1800  3612
>  41  22   0  35   0   1|8952k   40M|  54B   65B|   0     0 |1493  3471
>  21  24   0  54   0   1|2040k   42M|1469B 1591B|   0     0 |2180  5170
>  16  24   0  59   0   1|  14M   44M|  25k 4962B|   0     0 |1991  4541
>  12  11  17  58   0   2|  36M   19M|  28k 2964B|  44k    0 |2351  3774
>  19  28  14  37   0   1|  40M   19M|  72k 5062B|   0     0 |1707  3906
>  14  29   0  54   0   3|  58M   42M| 108k 7586B|   0     0 |2431  4646
>   8  23   0  67   0   2|  44M   35M|  77k 4188B|   0     0 |2948  4587
>  22  19   6  50   0   1|  30M   38M|  41k 2666B|   0     0 |2127  3924
>   6  33  29  31   0   1|  52M   38M|7628B 1511B|   0     0 |2055  3375
>   4  25   0  70   0   1|4624k   39M|4447B 1429B|   0     0 |1808  2749
>  10  32   3  52   1   2|  53M   42M|  27k 2296B|   0     0 |2144  4474
>   5  17   0  77   0   1|  88k   38M|5515B  420B|   0     0 |2261  3338
>   6  24   1  67   0   1|  66M   37M|   0     0 |   0     0 |2741  4099
>   2  27  17  53   0   1|  64M   32M|   0     0 |  32k    0 |2331  3356
>   2  35  17  43   0   2|  71M   39M|   0     0 |   0     0 |2460  3713
>   3  33   5  57   0   2|  69M   40M| 189B  202B|   0     0 |2212  3366
>   1  36   0  61   0   1|  72M   42M|   0     0 |   0     0 |2296  3481
>   1  35   0  62   0   2|  69M   40M|   0    65B|   0     0 |2235  3425
>   2  24   0  73   0   1|  37M   39M|   0     0 |   0     0 |2033  2912 ^C
>
> The above 2 results are from a 2.5" SATA disk attached to a USB 2.0
> enclosure which has one USB connector connected to the laptop's USB port.
> This is a self-powered disk enclosure. Filesystems is use were, vfat for
> the former result and ext3 for the latter.
>
> Below are results from a different disk.
>
> ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
>  10  17  26  44   0   2|  32M   35M|   0     0 |   0     0 |3889    18k
>  12  20  34  35   0   0|  34M   36M|   0     0 |   0     0 |3923    19k
>  14  20  21  42   0   1|  36M   36M|   0   648B|   0     0 |4036    20k
>  14  22  21  41   0   0|  45M   37M|   0   324B|   0     0 |4140    24k
>  15  21  10  52   0   2|  35M   35M| 448B  520B|   0     0 |3947    19k
>  10  19  31  40   0   0|  30M   35M|   0     0 |   0     0 |3885    17k
>  18  22  14  46   0   0|  36M   37M|  92B    0 |   0     0 |4029    21k
>  16  21  18  43   0   1|  40M   36M|  92B    0 |   0     0 |3966    21k
>  11  23  28  37   0   0|  37M   36M|  92B    0 |   0     0 |3986    20k
>  11  17  31  41   0   0|  30M   35M|   0     0 |   0     0 |3893    19k
>  12  19   6  62   0   1|  29M   34M|   0     0 |   0     0 |3895    18k
>  12  19   0  67   0   2|  29M   35M|   0     0 |   0     0 |3974    17k
>  17  15   0  66   0   1|  15M   33M|   0     0 |   0     0 |3802    11k
>  32  17   5  46   0   0|  27M   36M| 108B  357B|   0     0 |3943    14k
>  17  14   2  65   0   1|  14M   33M|   0     0 |   0     0 |3884    11k
>  21  20  17  40   0   2|  28M   35M|   0     0 |   0     0 |3916    17k
>  17  24   8  50   0   0|  40M   37M|  55B   96B|   0     0 |3982    22k
>  19  27  13  41   0   0|  52M   37M|   0     0 |   0     0 |4265    29k
>  20  25  13  42   0   0|  40M   36M|   0     0 |   0     0 |3979    22k
>  21  28   8  41   1   2|  52M   36M| 420B  520B|   0     0 |4082    27k
>  20  32  16  31   0   0|  68M   38M|   0     0 |   0     0 |4343    33k^C
>
> This result is from a 2.5" SATA disk connected to a USB 2.0 enclosure with
> 2 USB connectors connected to the laptop. The filesystem is fuse (ntfs-3g).
> Looks good.
>
>
> Here's the interesting one.
>
> ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
>  11   3  82   2   0   1|1655k  267k|   0     0 |5486B   12k|1259  1863
>  16  23  25  35   0   0|1360k    0 |3022B  336B|  32k    0 | 972  3043
>   2  44  15  40   0   0|  64k    0 |   0     0 |   0     0 | 902  1141
>   4   3  93   0   0   0|   0     0 |   0     0 |   0     0 | 769  1235
>   5   2  92   0   0   0|   0   368k| 426B  520B|   0     0 | 557  1100
>   4   3  93   0   0   0|   0     0 |  92B    0 |   0     0 | 506  1041
>   4   3  94   0   0   0|   0     0 |   0     0 |   0     0 | 628  1005
>   4   2  93   0   0   0|   0     0 |   0     0 |   0     0 | 547  1036
>   6   2  92   0   0   0|   0     0 |   0     0 |   0     0 | 574   995
>   4   2  94   0   0   0|   0     0 |   0     0 |   0     0 | 593  1126
>   6   3  91   0   0   0|   0     0 | 141B   84B|   0     0 | 684  1165
>   4   3  93   0   0   0|   0     0 |   0     0 |   0     0 | 514  1044
>   4   2  93   0   0   0|   0     0 |   0     0 |   0     0 | 485   850
>   4   3  92   0   0   0|   0     0 | 227B  484B|   0     0 | 645  1116
>   3   2  94   0   0   0|   0     0 |   0     0 |   0     0 | 619  1009
>   4   3  92   1   0   0|8192B 1472k| 108B  292B|   0     0 | 608  1072
>   5   3  92   0   0   0|   0     0 | 187B   72B|   0     0 | 786  1208
>   4   2  94   0   0   0|   0     0 |   0     0 |   0     0 | 587  1098
>   3   3  94   0   0   0|   0     0 |   0     0 |   0     0 | 500   939 ^C
>
>
> This result is from a *3.5"* ATA disk connected to a USB 2.0 enclosure with
> 2 USB connectors connected to the laptop. The enclosure is externally
> powered. The disk is partition-less. The entire disk (/dev/sdb) is LUKS
> encrypted. The filesystem is ext3.
>
> As soon as I initiated the I/O, the performance went down (as mentioned in
> the above result). Also, the usb port was reset immediately which resulted
> in a read-only filesystem.
>
> Here are the relevant logs.
>
> [44125.008940] usb 5-8: new high speed USB device using ehci_hcd and
> address 10
> [44125.375160] usb 4-2: new full speed USB device using uhci_hcd and
> address 2 [44125.488926] usb 4-2: device descriptor read/64, error -71
> [44125.717839] usb 4-2: not running at top speed; connect to a high speed
> hub [44125.732838] usb 4-2: configuration #1 chosen from 1 choice
> [44125.735518] scsi5 : SCSI emulation for USB Mass Storage devices
> [44125.736912] usb 4-2: New USB device found, idVendor=05e3, idProduct=0702
> [44125.736928] usb 4-2: New USB device strings: Mfr=0, Product=1,
> SerialNumber=0
> [44125.736933] usb 4-2: Product: USB TO IDE
> [44125.737807] usb-storage: device found at 2
> [44125.737814] usb-storage: waiting for device to settle before scanning
> [44130.771126] usb-storage: device scan complete
> [44130.774592] scsi 5:0:0:0: Direct-Access     ST325082 4A              
> 0811 PQ: 0 ANSI: 0
> [44130.780522] sd 5:0:0:0: [sdb] 488397168 512-byte hardware sectors
> (250059 MB)
> [44130.787520] sd 5:0:0:0: [sdb] Test WP failed, assume Write Enabled
> [44130.787520] sd 5:0:0:0: [sdb] Assuming drive cache: write through
> [44130.792520] sd 5:0:0:0: [sdb] 488397168 512-byte hardware sectors
> (250059 MB)
> [44130.799520] sd 5:0:0:0: [sdb] Test WP failed, assume Write Enabled
> [44130.799520] sd 5:0:0:0: [sdb] Assuming drive cache: write through
> [44130.799520]  sdb: unknown partition table
> [44130.830056] sd 5:0:0:0: [sdb] Attached SCSI disk
> [44130.830056] sd 5:0:0:0: Attached scsi generic sg2 type 0
> [44273.057272] kjournald starting.  Commit interval 5 seconds
> [44273.064954] EXT3 FS on dm-2, internal journal
> [44273.065232] EXT3-fs: mounted filesystem with ordered data mode.
> [44306.991719] usb 4-2: reset full speed USB device using uhci_hcd and
> address 2
> [44307.232054] usb 4-2: reset full speed USB device using uhci_hcd and
> address 2
> [44307.468171] usb 4-2: reset full speed USB device using uhci_hcd and
> address 2
> [44307.600787] usb 4-2: failed to restore interface 0 altsetting 0
> (error=-71) [44307.601609] usb 4-2: USB disconnect, address 2
> [44307.601609] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.601609] end_request: I/O error, dev sdb, sector 248121664
> [44307.601609] Buffer I/O error on device dm-2, logical block 31015079
> [44307.601609] lost page write due to I/O error on dm-2
> [44307.601609] Buffer I/O error on device dm-2, logical block 31015080
> [44307.601609] lost page write due to I/O error on dm-2
> [44307.601609] Buffer I/O error on device dm-2, logical block 31015081
> [44307.601609] lost page write due to I/O error on dm-2
> [44307.601609] Buffer I/O error on device dm-2, logical block 31015082
> [44307.601609] lost page write due to I/O error on dm-2
> [44307.601635] Buffer I/O error on device dm-2, logical block 31015083
> [44307.601639] lost page write due to I/O error on dm-2
> [44307.601648] Buffer I/O error on device dm-2, logical block 31015084
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] Buffer I/O error on device dm-2, logical block 31015085
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] Buffer I/O error on device dm-2, logical block 31015086
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602572] end_request: I/O error, dev sdb, sector 248121728
> [44307.602572] Buffer I/O error on device dm-2, logical block 31015087
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] Buffer I/O error on device dm-2, logical block 31015088
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602572] end_request: I/O error, dev sdb, sector 248121792
> [44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602572] end_request: I/O error, dev sdb, sector 248121856
> [44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602572] end_request: I/O error, dev sdb, sector 248121920
> [44307.602573] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602573] end_request: I/O error, dev sdb, sector 248121984
> [44307.603601] sd 5:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.603609] end_request: I/O error, dev sdb, sector 248122048
> [44307.604568] sd 5:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.604568] end_request: I/O error, dev sdb, sector 248122112
> [44307.625509] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44307.763898] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44307.763898] ------------[ cut here ]------------
> [44307.763898] WARNING: at fs/buffer.c:1186 mark_buffer_dirty+0x20/0x67()
> [44307.763898] Modules linked in: sha256_generic aes_i586 aes_generic cbc
> nls_utf8 nls_cp437 vfat fat nls_base usb_storage usbhid hid ff_memless
> tcp_diag inet_diag tun nvidia(P) rfcomm l2cap bluetooth xt_limit
> nf_conntrack_ipv6 ipv6 nf_conntrack_proto_dccp ts_kmp nf_conntrack_amanda
> nf_conntrack_irc nf_conntrack_sip nf_conntrack_netbios_ns nf_conntrack_pptp
> nf_conntrack_proto_gre nf_conntrack_netlink nfnetlink nf_conntrack_ftp
> nf_conntrack_tftp nf_conntrack_sane xt_conntrack nf_conntrack_proto_sctp
> nf_conntrack_proto_udplite nf_conntrack_h323 acpi_cpufreq
> cpufreq_conservative cpufreq_stats cpufreq_userspace cpufreq_powersave
> ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 xt_state nf_conntrack
> ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables bridge kvm_intel kvm
> fuse configfs loop firewire_sbp2 dm_crypt snd_hda_intel snd_usb_audio
> snd_pcm_oss snd_mixer_oss snd_pcm snd_usb_lib snd_hwdep arc4 snd_seq_dummy
> ecb crypto_blkcipher snd_seq_oss snd_seq_midi snd_rawmidi uvcvideo iwl3945
> snd_seq_midi_event compat_ioctl32 snd_seq joydev mac80211 videodev i2c_i801
> snd_timer snd_seq_device iTCO_wdt led_class serio_raw snd v4l1_compat
> intel_agp wmi rng_core i2c_core ac cfg80211 psmouse pcspkr agpgart button
> battery video output soundcore snd_page_alloc evdev dcdbas ext3 jbd mbcache
> dm_mirror dm_log dm_snapshot dm_mod sg sr_mod cdrom sd_mod ata_generic
> ata_piix firewire_ohci firewire_core libata scsi_mod crc_itu_t dock b44
> ide_pci_generic ide_core ohci1394 sdhci ieee1394 mmc_core ricoh_mmc ssb
> pcmcia pcmcia_core
> firmware_class mii ehci_hcd uhci_hcd usbcore thermal processor fan
> thermal_sys [44307.763898] Pid: 8632, comm: cp Tainted: P         
> 2.6.26-custom #1 [44307.763921]  [<c01219c0>] warn_on_slowpath+0x40/0x79
> [44307.763921]  [<c0119aee>] check_preempt_wakeup+0x97/0xd1
> [44307.763921]  [<c011a404>] try_to_wake_up+0xe8/0xf1
> [44307.763922]  [<c023397e>] vt_console_print+0x32/0x278
> [44307.763922]  [<c023397e>] vt_console_print+0x32/0x278
> [44307.763922]  [<c023394c>] vt_console_print+0x0/0x278
> [44307.763937]  [<c0121c56>] __call_console_drivers+0x4f/0x5b
> [44307.763950]  [<c013484a>] up+0x9/0x2a
> [44307.763969]  [<c0122066>] release_console_sem+0x172/0x18b
> [44307.764087]  [<c0194ed5>] mark_buffer_dirty+0x20/0x67
> [44307.764102]  [<f8b9dccb>] ext3_commit_super+0x3a/0x4e [ext3]
> [44307.764147]  [<f8b9f0e2>] ext3_handle_error+0x6e/0x8e [ext3]
> [44307.764178]  [<f8b9f18d>] ext3_error+0x3a/0x40 [ext3]
> [44307.764237]  [<f8b94707>] read_block_bitmap+0x90/0x115 [ext3]
> [44307.764307]  [<f8b95272>] ext3_new_blocks+0x199/0x569 [ext3]
> [44307.764395]  [<f8b98c45>] ext3_get_blocks_handle+0x332/0x785 [ext3]
> [44307.764395]  [<c0194ac9>] __find_get_block+0x162/0x16c
> [44307.764395]  [<c015bad2>] __rmqueue+0x16/0x1b5
> [44307.764395]  [<f8b99137>] ext3_get_block+0x9f/0xd3 [ext3]
> [44307.764469]  [<c0195ef8>] __block_prepare_write+0x16e/0x373
> [44307.764469]  [<c0196245>] block_write_begin+0x6c/0xc3
> [44307.764469]  [<f8b99098>] ext3_get_block+0x0/0xd3 [ext3]
> [44307.764469]  [<f8b98814>] ext3_write_begin+0xc1/0x168 [ext3]
> [44307.764487]  [<f8b99098>] ext3_get_block+0x0/0xd3 [ext3]
> [44307.764896]  [<c015912d>] generic_file_buffered_write+0xfa/0x56a
> [44307.764997]  [<f8b11925>] journal_stop+0x145/0x14e [jbd]
> [44307.765065]  [<c0159b98>] __generic_file_aio_write_nolock+0x3fa/0x445
> [44307.765141]  [<c018acfa>] mnt_want_write+0x1a/0x5e
> [44307.765157]  [<c018b649>] mnt_drop_write+0x1a/0xb2
> [44307.765172]  [<c015a194>] generic_file_aio_read+0x474/0x4fa
> [44307.765203]  [<c0159c43>] generic_file_aio_write+0x60/0xb7
> [44307.765253]  [<f8b95f6c>] ext3_file_write+0x19/0x85 [ext3]
> [44307.765289]  [<c017815d>] do_sync_write+0xc0/0x107
> [44307.765369]  [<c013140a>] autoremove_wake_function+0x0/0x2d
> [44307.765394]  [<c011e114>] hrtick_set+0x7b/0xe6
> [44307.765455]  [<c017809d>] do_sync_write+0x0/0x107
> [44307.765469]  [<c01789d9>] vfs_write+0x84/0x121
> [44307.765495]  [<c0178b0e>] sys_write+0x3c/0x63
> [44307.765525]  [<c010398a>] syscall_call+0x7/0xb
> [44307.765894]  =======================
> [44307.765894] ---[ end trace 2a0ce193654d04fb ]---
> [44307.884076] usb 4-2: new full speed USB device using uhci_hcd and
> address 3 [44308.017388] usb 4-2: device descriptor read/all, error -71
> [44308.026550] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.047000] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.056026] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.075044] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.090090] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.102860] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.117901] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.122647] usb 4-2: new full speed USB device using uhci_hcd and
> address 4 [44308.127745] EXT3-fs error (device dm-2): read_block_bitmap:
> Cannot read block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.136581] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.150331] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.159068] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.168617] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.185580] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.200611] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.204343] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.217310] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.228915] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.254557] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.270601] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.300419] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.301453] usb 4-2: string descriptor 0 read error: -71
> [44308.301572] usb 4-2: configuration #1 chosen from 1 choice
> [44308.308850] usb 4-2: can't set config #1, error -71
> [44308.308899] usb 4-2: New USB device found, idVendor=05e3, idProduct=0702
> [44308.308899] usb 4-2: New USB device strings: Mfr=0, Product=1,
> SerialNumber=0
> [44308.328418] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.336523] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.367727] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.384314] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.399502] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.423943] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.439201] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.450486] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.460527] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.464059] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.477362] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.498686] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.516538] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.520738] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.540687] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.557256] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.579235] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.590239] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.605335] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.628031] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.990689] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44309.667656] Aborting journal on device dm-2.
> [44309.668659] __journal_remove_journal_head: freeing b_committed_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.679137] ext3_abort called.
> [44309.679137] EXT3-fs error (device dm-2): ext3_journal_start_sb: Detected
> aborted journal
> [44309.679137] Remounting filesystem read-only
> [44338.161517] __ratelimit: 26116 messages suppressed
> [44338.161517] Buffer I/O error on device dm-2, logical block 8
> [44338.161517] lost page write due to I/O error on dm-2
> [44338.161517] Buffer I/O error on device dm-2, logical block 1027
> [44338.161517] lost page write due to I/O error on dm-2
> [44338.161517] Buffer I/O error on device dm-2, logical block 1539
> [44338.161517] lost page write due to I/O error on dm-2
> [44338.161531] Buffer I/O error on device dm-2, logical block 30998528
> [44338.161538] lost page write due to I/O error on dm-2
> [44338.162759] Buffer I/O error on device dm-2, logical block 30998529
> [44338.162767] lost page write due to I/O error on dm-2
> [44338.162776] Buffer I/O error on device dm-2, logical block 30998530
> [44338.162781] lost page write due to I/O error on dm-2
>
>
> This makes me feel that it might be a hardware issue.
>
> Ritesh

-- 
Ritesh Raj Sarraf
RESEARCHUT - http://www.researchut.com
"Necessity is the mother of invention."


[-- Attachment #1.2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 197 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]



^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [dm-devel] dm-crypt low performance
  2009-01-13 17:37     ` Ritesh Raj Sarraf
  2009-01-13 19:52       ` Ritesh Raj Sarraf
@ 2009-01-13 19:52       ` Ritesh Raj Sarraf
  1 sibling, 0 replies; 10+ messages in thread
From: Ritesh Raj Sarraf @ 2009-01-13 19:52 UTC (permalink / raw)
  To: Milan Broz; +Cc: device-mapper development, linux-pm


[-- Attachment #1.1: Type: text/plain, Size: 31650 bytes --]

Okay!! I think I now have the correct steps to reproduce it consistently.

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--  
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw   
 10  25   0  64   0   1| 128k   15M| 158B    0 |   0     0 |3475  6007
 10  35   0  53   0   2|  75M   15M|   0     0 |   0     0 |3741  6414
  9  35   7  47   0   1|  74M   15M|   0     0 |   0     0 |3798  6372
  9  36   3  50   0   2|  72M   13M|   0     0 |   0     0 |3476  5915
  9  28   0  62   0   1|  31M   14M|   0     0 |   0     0 |3455  5850
 10  23   0  65   0   1|   0    14M|  92B    0 |   0     0 |3103  5343
  3  21   0  75   0   1|   0    13M|  92B    0 |   0     0 |3056  4698
  2  21   0  76   0   1|   0    14M|  92B    0 |   0     0 |3121  4699
  3  20   0  76   0   1|   0    13M|   0     0 |   0     0 |2973  4487
  1  20   0  78   0   1|   0    13M|   0    65B|   0     0 |2991  4487
  4  22   0  72   0   1|  15M   13M|   0     0 |   0     0 |3147  4881
 10  21   5  63   0   1|  70M 3084k|   0     0 |   0     0 |2658  4568
  9  32  11  46   0   1|  72M 9848k|   0     0 |   0     0 |3192  5481
 10  37   0  51   0   2|  74M   17M|   0     0 |   0     0 |4042  6892
 10  28   0  61   0   1|  23M   16M|   0     0 |   0     0 |3619  6116
  2  26   0  71   0   1|   0    17M|   0     0 |   0     0 |3748  5736
  5  29   2  63   0   1|  34M   16M|   0     0 |   0     0 |3763  6144
  4  34   4  56   0   2|  40M   17M|   0     0 |   0     0 |3895  6392
  7  34   0  58   0   2|  44M   18M|   0     0 |   0     0 |3993  6056
 15  31   0  51   1   1|  50M   18M|   0    65B|   0  4096B|3816  7130
  1  37   0  60   0   2|  72M   17M|   0     0 |   0     0 |4079  6412 ^C

The above result is from a freshly booted linux with the same suspected faulty 
USB HDD enclosure. I ran it on 2 kernels, one standard and one debug, and both 
gave similar results.
So shouldn't be faulty hardware.


So then with my standard kernel, I booted + hibernated and then resumed and 
then again ran the I/O. Here are the same results.

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  1   1   0  97   0   0|   0   896k|  54B    0 |   0     0 | 666   778 
  2   2   0  95   0   0|   0   864k|  54B   78B|   0     0 | 693   834 
  1   1   0  98   0   0|   0   864k|   0     0 |   0     0 | 649   691 
  1   1   0  98   0   0|   0   896k|   0     0 |   0     0 | 655   727 
  2   2   0  96   0   0|   0  1112k|   0     0 |   0     0 | 700   854 
  2   1   0  97   0   0|   0  1032k|   0     0 |   0     0 | 669   865 
  2   1   0  96   0   0|   0  1048k|   0     0 |   0     0 | 650   816 
  2   2   0  97   0   0|   0   896k|   0     0 |   0     0 | 663   808 
  0   2   0  98   0   0|   0   864k|   0     0 |   0     0 | 635   686 
  3  13   0  82   0   0|  59M  928k|   0     0 |   0     0 |1326  1393 
  1  13   0  86   0   0|  74M  896k|   0     0 |   0     0 |1472  1388 
  2   8   0  90   0   0|  40M  928k|   0     0 |   0     0 |1163  1195 
  1   1   0  97   0   0|   0   864k|   0     0 |   0     0 | 738   829 
  2   2   0  96   0   0|   0   896k|   0     0 |   0     0 | 787   902 
  1   2   0  97   0   0|   0  1048k|   0     0 |   0     0 | 766   911 
  1   1   0  97   0   0|   0   896k|  92B    0 |   0     0 | 766   927 
  2   2  30  66   0   0|   0  1080k|  92B    0 |   0     0 | 750   868 
  1   1  51  47   0   0|   0   864k|  92B    0 |   0     0 | 712   808 
  1   1  50  47   0   0|   0   896k|  92B    0 |   0     0 | 722   872 
  1   2  10  86   0   0|   0   864k| 184B    0 |   0     0 | 748   972 
  1   1   0  98   0   0|   0   864k|  92B    0 |   0     0 | 730   817 

So this seems to be happening on my laptop when the OS has used the 
hibernation feature. I'm of-course doing a luksClose and USB device 
disconnection before hibernation.

Here's the usb device listing after hibernation/resume.

rrs@learner:~$ cat /tmp/lsusb.suspend
Bus 005 Device 005: ID 046d:08c6 Logitech, Inc. QuickCam for DELL Notebooks
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 007: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 005: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub


And here's the usb device listing after a fresh boot.

rrs@learner:~$ lsusb
Bus 005 Device 004: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
Bus 005 Device 003: ID 046d:08c6 Logitech, Inc. QuickCam for DELL Notebooks
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 004: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub


Ritesh




On Tuesday 13 Jan 2009 23:07:45 Ritesh Raj Sarraf wrote:
> On Tuesday 13 Jan 2009 21:20:48 Milan Broz wrote:
> > Ritesh Raj Sarraf wrote:
> > > I'm using dm-crypt on an external USB enclosure ide hdd. I copied 20Gb
> > > of data on to the encrypted device and am suffering severe performance
> > > penalty. After a couple of seconds, all processes involved in the I/O
> > > keep stalling. They periodically resume, just for a couple of seconds
> > > and then again stall.
> > >
> > > Running linux 2.6.26.
> >
> > Please can you try it without dm-crypt involved?
> > Just copy 20Gb to your unencrypted disk attached through USB.
> >
> > I saw this problem with plain USB attached storage some time ago too.
> >
> > There is only one thread in dm-crypt and it is waiting for io_schedule,
> > so I think it is not dm-crypt who is blocking it, but the layer
> > below the dm-crypt.
>
> So I tried the following.
>
> Copied 20Gb of data to a partition on the External USB disk. Here are the
> results:
>
> ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
>  11  10   0  79   0   1|  22M   39M|2864B 2454B|   0     0 |2048  3793
>  12   9   1  76   0   1|  23M   39M|  81k 8686B|   0     0 |2166  3635
>  13   8  16  62   0   1|  27M   43M|  12k 5036B|   0     0 |2127  3526
>  14   8  37  40   0   1|  24M   42M|7138B 5140B|   0     0 |2047  3415
>   7   8  47  36   0   0|  35M   40M|2451B 2538B|   0     0 |2002  3179
>   4   9  49  37   0   0|  41M   40M|4081B  276B|   0     0 |1974  2956
>   1   9  50  38   0   1|  40M   40M|   0   276B|   0     0 |1912  2774
>   1   8  50  39   0   1|  40M   40M|  92B    0 |   0     0 |2018  2958
>   2   9  48  39   0   0|  44M   40M| 362B  276B|   0     0 |2097  3191
>   8   8  45  38   0   1|  27M   33M|  23k 4181B|   0     0 |1919  3009
>   8   8  50  34   0   0|  31M   26M|  10k 2570B|   0     0 |1760  2724
>  21  11  33  30   0   3|  40M   40M| 204k   17k|   0     0 |2360  3845
>  13   8  43  36   0   0|  35M   39M|  12k 5354B|   0     0 |2083  3349
>  16   8  41  35   0   0|  30M   35M|5738B 4158B|   0     0 |1904  3118
>   8  10  47  33   0   1|  40M   37M|1718B 1255B|   0     0 |1932  3130
>   3   9  49  39   0   1|  40M   40M|   0     0 |   0     0 |2124  3065
>   4   9  46  41   0   0|  40M   40M|   0     0 |   0     0 |1971  3088
>   6   9  46  40   0   0|  40M   41M| 850B  723B|   0     0 |2059  3155
>   3  10  46  39   0   1|  40M   42M|1958B 1651B|   0     0 |2054  3217
>   8  12  41  38   0   1|  41M   39M|2741B 1342B|   0     0 |2083  3647
>   4   8  47  40   0   0|  39M   39M|2062B 1299B|   0     0 |2060  3328
>
> Looks good.
>
> Then I tried copying 20Gb of data to the dm-crypted partition on the same
> USB disk. Here are the results:
>
> ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
>   3  28   0  67   0   1|  20M   41M|   0     0 |   0     0 |1972  3036
>  25  29   0  44   0   2|  39M   42M|   0    78B|  52k    0 |1800  3612
>  41  22   0  35   0   1|8952k   40M|  54B   65B|   0     0 |1493  3471
>  21  24   0  54   0   1|2040k   42M|1469B 1591B|   0     0 |2180  5170
>  16  24   0  59   0   1|  14M   44M|  25k 4962B|   0     0 |1991  4541
>  12  11  17  58   0   2|  36M   19M|  28k 2964B|  44k    0 |2351  3774
>  19  28  14  37   0   1|  40M   19M|  72k 5062B|   0     0 |1707  3906
>  14  29   0  54   0   3|  58M   42M| 108k 7586B|   0     0 |2431  4646
>   8  23   0  67   0   2|  44M   35M|  77k 4188B|   0     0 |2948  4587
>  22  19   6  50   0   1|  30M   38M|  41k 2666B|   0     0 |2127  3924
>   6  33  29  31   0   1|  52M   38M|7628B 1511B|   0     0 |2055  3375
>   4  25   0  70   0   1|4624k   39M|4447B 1429B|   0     0 |1808  2749
>  10  32   3  52   1   2|  53M   42M|  27k 2296B|   0     0 |2144  4474
>   5  17   0  77   0   1|  88k   38M|5515B  420B|   0     0 |2261  3338
>   6  24   1  67   0   1|  66M   37M|   0     0 |   0     0 |2741  4099
>   2  27  17  53   0   1|  64M   32M|   0     0 |  32k    0 |2331  3356
>   2  35  17  43   0   2|  71M   39M|   0     0 |   0     0 |2460  3713
>   3  33   5  57   0   2|  69M   40M| 189B  202B|   0     0 |2212  3366
>   1  36   0  61   0   1|  72M   42M|   0     0 |   0     0 |2296  3481
>   1  35   0  62   0   2|  69M   40M|   0    65B|   0     0 |2235  3425
>   2  24   0  73   0   1|  37M   39M|   0     0 |   0     0 |2033  2912 ^C
>
> The above 2 results are from a 2.5" SATA disk attached to a USB 2.0
> enclosure which has one USB connector connected to the laptop's USB port.
> This is a self-powered disk enclosure. Filesystems is use were, vfat for
> the former result and ext3 for the latter.
>
> Below are results from a different disk.
>
> ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
>  10  17  26  44   0   2|  32M   35M|   0     0 |   0     0 |3889    18k
>  12  20  34  35   0   0|  34M   36M|   0     0 |   0     0 |3923    19k
>  14  20  21  42   0   1|  36M   36M|   0   648B|   0     0 |4036    20k
>  14  22  21  41   0   0|  45M   37M|   0   324B|   0     0 |4140    24k
>  15  21  10  52   0   2|  35M   35M| 448B  520B|   0     0 |3947    19k
>  10  19  31  40   0   0|  30M   35M|   0     0 |   0     0 |3885    17k
>  18  22  14  46   0   0|  36M   37M|  92B    0 |   0     0 |4029    21k
>  16  21  18  43   0   1|  40M   36M|  92B    0 |   0     0 |3966    21k
>  11  23  28  37   0   0|  37M   36M|  92B    0 |   0     0 |3986    20k
>  11  17  31  41   0   0|  30M   35M|   0     0 |   0     0 |3893    19k
>  12  19   6  62   0   1|  29M   34M|   0     0 |   0     0 |3895    18k
>  12  19   0  67   0   2|  29M   35M|   0     0 |   0     0 |3974    17k
>  17  15   0  66   0   1|  15M   33M|   0     0 |   0     0 |3802    11k
>  32  17   5  46   0   0|  27M   36M| 108B  357B|   0     0 |3943    14k
>  17  14   2  65   0   1|  14M   33M|   0     0 |   0     0 |3884    11k
>  21  20  17  40   0   2|  28M   35M|   0     0 |   0     0 |3916    17k
>  17  24   8  50   0   0|  40M   37M|  55B   96B|   0     0 |3982    22k
>  19  27  13  41   0   0|  52M   37M|   0     0 |   0     0 |4265    29k
>  20  25  13  42   0   0|  40M   36M|   0     0 |   0     0 |3979    22k
>  21  28   8  41   1   2|  52M   36M| 420B  520B|   0     0 |4082    27k
>  20  32  16  31   0   0|  68M   38M|   0     0 |   0     0 |4343    33k^C
>
> This result is from a 2.5" SATA disk connected to a USB 2.0 enclosure with
> 2 USB connectors connected to the laptop. The filesystem is fuse (ntfs-3g).
> Looks good.
>
>
> Here's the interesting one.
>
> ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
>  11   3  82   2   0   1|1655k  267k|   0     0 |5486B   12k|1259  1863
>  16  23  25  35   0   0|1360k    0 |3022B  336B|  32k    0 | 972  3043
>   2  44  15  40   0   0|  64k    0 |   0     0 |   0     0 | 902  1141
>   4   3  93   0   0   0|   0     0 |   0     0 |   0     0 | 769  1235
>   5   2  92   0   0   0|   0   368k| 426B  520B|   0     0 | 557  1100
>   4   3  93   0   0   0|   0     0 |  92B    0 |   0     0 | 506  1041
>   4   3  94   0   0   0|   0     0 |   0     0 |   0     0 | 628  1005
>   4   2  93   0   0   0|   0     0 |   0     0 |   0     0 | 547  1036
>   6   2  92   0   0   0|   0     0 |   0     0 |   0     0 | 574   995
>   4   2  94   0   0   0|   0     0 |   0     0 |   0     0 | 593  1126
>   6   3  91   0   0   0|   0     0 | 141B   84B|   0     0 | 684  1165
>   4   3  93   0   0   0|   0     0 |   0     0 |   0     0 | 514  1044
>   4   2  93   0   0   0|   0     0 |   0     0 |   0     0 | 485   850
>   4   3  92   0   0   0|   0     0 | 227B  484B|   0     0 | 645  1116
>   3   2  94   0   0   0|   0     0 |   0     0 |   0     0 | 619  1009
>   4   3  92   1   0   0|8192B 1472k| 108B  292B|   0     0 | 608  1072
>   5   3  92   0   0   0|   0     0 | 187B   72B|   0     0 | 786  1208
>   4   2  94   0   0   0|   0     0 |   0     0 |   0     0 | 587  1098
>   3   3  94   0   0   0|   0     0 |   0     0 |   0     0 | 500   939 ^C
>
>
> This result is from a *3.5"* ATA disk connected to a USB 2.0 enclosure with
> 2 USB connectors connected to the laptop. The enclosure is externally
> powered. The disk is partition-less. The entire disk (/dev/sdb) is LUKS
> encrypted. The filesystem is ext3.
>
> As soon as I initiated the I/O, the performance went down (as mentioned in
> the above result). Also, the usb port was reset immediately which resulted
> in a read-only filesystem.
>
> Here are the relevant logs.
>
> [44125.008940] usb 5-8: new high speed USB device using ehci_hcd and
> address 10
> [44125.375160] usb 4-2: new full speed USB device using uhci_hcd and
> address 2 [44125.488926] usb 4-2: device descriptor read/64, error -71
> [44125.717839] usb 4-2: not running at top speed; connect to a high speed
> hub [44125.732838] usb 4-2: configuration #1 chosen from 1 choice
> [44125.735518] scsi5 : SCSI emulation for USB Mass Storage devices
> [44125.736912] usb 4-2: New USB device found, idVendor=05e3, idProduct=0702
> [44125.736928] usb 4-2: New USB device strings: Mfr=0, Product=1,
> SerialNumber=0
> [44125.736933] usb 4-2: Product: USB TO IDE
> [44125.737807] usb-storage: device found at 2
> [44125.737814] usb-storage: waiting for device to settle before scanning
> [44130.771126] usb-storage: device scan complete
> [44130.774592] scsi 5:0:0:0: Direct-Access     ST325082 4A              
> 0811 PQ: 0 ANSI: 0
> [44130.780522] sd 5:0:0:0: [sdb] 488397168 512-byte hardware sectors
> (250059 MB)
> [44130.787520] sd 5:0:0:0: [sdb] Test WP failed, assume Write Enabled
> [44130.787520] sd 5:0:0:0: [sdb] Assuming drive cache: write through
> [44130.792520] sd 5:0:0:0: [sdb] 488397168 512-byte hardware sectors
> (250059 MB)
> [44130.799520] sd 5:0:0:0: [sdb] Test WP failed, assume Write Enabled
> [44130.799520] sd 5:0:0:0: [sdb] Assuming drive cache: write through
> [44130.799520]  sdb: unknown partition table
> [44130.830056] sd 5:0:0:0: [sdb] Attached SCSI disk
> [44130.830056] sd 5:0:0:0: Attached scsi generic sg2 type 0
> [44273.057272] kjournald starting.  Commit interval 5 seconds
> [44273.064954] EXT3 FS on dm-2, internal journal
> [44273.065232] EXT3-fs: mounted filesystem with ordered data mode.
> [44306.991719] usb 4-2: reset full speed USB device using uhci_hcd and
> address 2
> [44307.232054] usb 4-2: reset full speed USB device using uhci_hcd and
> address 2
> [44307.468171] usb 4-2: reset full speed USB device using uhci_hcd and
> address 2
> [44307.600787] usb 4-2: failed to restore interface 0 altsetting 0
> (error=-71) [44307.601609] usb 4-2: USB disconnect, address 2
> [44307.601609] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.601609] end_request: I/O error, dev sdb, sector 248121664
> [44307.601609] Buffer I/O error on device dm-2, logical block 31015079
> [44307.601609] lost page write due to I/O error on dm-2
> [44307.601609] Buffer I/O error on device dm-2, logical block 31015080
> [44307.601609] lost page write due to I/O error on dm-2
> [44307.601609] Buffer I/O error on device dm-2, logical block 31015081
> [44307.601609] lost page write due to I/O error on dm-2
> [44307.601609] Buffer I/O error on device dm-2, logical block 31015082
> [44307.601609] lost page write due to I/O error on dm-2
> [44307.601635] Buffer I/O error on device dm-2, logical block 31015083
> [44307.601639] lost page write due to I/O error on dm-2
> [44307.601648] Buffer I/O error on device dm-2, logical block 31015084
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] Buffer I/O error on device dm-2, logical block 31015085
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] Buffer I/O error on device dm-2, logical block 31015086
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602572] end_request: I/O error, dev sdb, sector 248121728
> [44307.602572] Buffer I/O error on device dm-2, logical block 31015087
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] Buffer I/O error on device dm-2, logical block 31015088
> [44307.602572] lost page write due to I/O error on dm-2
> [44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602572] end_request: I/O error, dev sdb, sector 248121792
> [44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602572] end_request: I/O error, dev sdb, sector 248121856
> [44307.602572] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602572] end_request: I/O error, dev sdb, sector 248121920
> [44307.602573] sd 5:0:0:0: [sdb] Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.602573] end_request: I/O error, dev sdb, sector 248121984
> [44307.603601] sd 5:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.603609] end_request: I/O error, dev sdb, sector 248122048
> [44307.604568] sd 5:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT
> driverbyte=DRIVER_OK,SUGGEST_OK
> [44307.604568] end_request: I/O error, dev sdb, sector 248122112
> [44307.625509] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44307.763898] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44307.763898] ------------[ cut here ]------------
> [44307.763898] WARNING: at fs/buffer.c:1186 mark_buffer_dirty+0x20/0x67()
> [44307.763898] Modules linked in: sha256_generic aes_i586 aes_generic cbc
> nls_utf8 nls_cp437 vfat fat nls_base usb_storage usbhid hid ff_memless
> tcp_diag inet_diag tun nvidia(P) rfcomm l2cap bluetooth xt_limit
> nf_conntrack_ipv6 ipv6 nf_conntrack_proto_dccp ts_kmp nf_conntrack_amanda
> nf_conntrack_irc nf_conntrack_sip nf_conntrack_netbios_ns nf_conntrack_pptp
> nf_conntrack_proto_gre nf_conntrack_netlink nfnetlink nf_conntrack_ftp
> nf_conntrack_tftp nf_conntrack_sane xt_conntrack nf_conntrack_proto_sctp
> nf_conntrack_proto_udplite nf_conntrack_h323 acpi_cpufreq
> cpufreq_conservative cpufreq_stats cpufreq_userspace cpufreq_powersave
> ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 xt_state nf_conntrack
> ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables bridge kvm_intel kvm
> fuse configfs loop firewire_sbp2 dm_crypt snd_hda_intel snd_usb_audio
> snd_pcm_oss snd_mixer_oss snd_pcm snd_usb_lib snd_hwdep arc4 snd_seq_dummy
> ecb crypto_blkcipher snd_seq_oss snd_seq_midi snd_rawmidi uvcvideo iwl3945
> snd_seq_midi_event compat_ioctl32 snd_seq joydev mac80211 videodev i2c_i801
> snd_timer snd_seq_device iTCO_wdt led_class serio_raw snd v4l1_compat
> intel_agp wmi rng_core i2c_core ac cfg80211 psmouse pcspkr agpgart button
> battery video output soundcore snd_page_alloc evdev dcdbas ext3 jbd mbcache
> dm_mirror dm_log dm_snapshot dm_mod sg sr_mod cdrom sd_mod ata_generic
> ata_piix firewire_ohci firewire_core libata scsi_mod crc_itu_t dock b44
> ide_pci_generic ide_core ohci1394 sdhci ieee1394 mmc_core ricoh_mmc ssb
> pcmcia pcmcia_core
> firmware_class mii ehci_hcd uhci_hcd usbcore thermal processor fan
> thermal_sys [44307.763898] Pid: 8632, comm: cp Tainted: P         
> 2.6.26-custom #1 [44307.763921]  [<c01219c0>] warn_on_slowpath+0x40/0x79
> [44307.763921]  [<c0119aee>] check_preempt_wakeup+0x97/0xd1
> [44307.763921]  [<c011a404>] try_to_wake_up+0xe8/0xf1
> [44307.763922]  [<c023397e>] vt_console_print+0x32/0x278
> [44307.763922]  [<c023397e>] vt_console_print+0x32/0x278
> [44307.763922]  [<c023394c>] vt_console_print+0x0/0x278
> [44307.763937]  [<c0121c56>] __call_console_drivers+0x4f/0x5b
> [44307.763950]  [<c013484a>] up+0x9/0x2a
> [44307.763969]  [<c0122066>] release_console_sem+0x172/0x18b
> [44307.764087]  [<c0194ed5>] mark_buffer_dirty+0x20/0x67
> [44307.764102]  [<f8b9dccb>] ext3_commit_super+0x3a/0x4e [ext3]
> [44307.764147]  [<f8b9f0e2>] ext3_handle_error+0x6e/0x8e [ext3]
> [44307.764178]  [<f8b9f18d>] ext3_error+0x3a/0x40 [ext3]
> [44307.764237]  [<f8b94707>] read_block_bitmap+0x90/0x115 [ext3]
> [44307.764307]  [<f8b95272>] ext3_new_blocks+0x199/0x569 [ext3]
> [44307.764395]  [<f8b98c45>] ext3_get_blocks_handle+0x332/0x785 [ext3]
> [44307.764395]  [<c0194ac9>] __find_get_block+0x162/0x16c
> [44307.764395]  [<c015bad2>] __rmqueue+0x16/0x1b5
> [44307.764395]  [<f8b99137>] ext3_get_block+0x9f/0xd3 [ext3]
> [44307.764469]  [<c0195ef8>] __block_prepare_write+0x16e/0x373
> [44307.764469]  [<c0196245>] block_write_begin+0x6c/0xc3
> [44307.764469]  [<f8b99098>] ext3_get_block+0x0/0xd3 [ext3]
> [44307.764469]  [<f8b98814>] ext3_write_begin+0xc1/0x168 [ext3]
> [44307.764487]  [<f8b99098>] ext3_get_block+0x0/0xd3 [ext3]
> [44307.764896]  [<c015912d>] generic_file_buffered_write+0xfa/0x56a
> [44307.764997]  [<f8b11925>] journal_stop+0x145/0x14e [jbd]
> [44307.765065]  [<c0159b98>] __generic_file_aio_write_nolock+0x3fa/0x445
> [44307.765141]  [<c018acfa>] mnt_want_write+0x1a/0x5e
> [44307.765157]  [<c018b649>] mnt_drop_write+0x1a/0xb2
> [44307.765172]  [<c015a194>] generic_file_aio_read+0x474/0x4fa
> [44307.765203]  [<c0159c43>] generic_file_aio_write+0x60/0xb7
> [44307.765253]  [<f8b95f6c>] ext3_file_write+0x19/0x85 [ext3]
> [44307.765289]  [<c017815d>] do_sync_write+0xc0/0x107
> [44307.765369]  [<c013140a>] autoremove_wake_function+0x0/0x2d
> [44307.765394]  [<c011e114>] hrtick_set+0x7b/0xe6
> [44307.765455]  [<c017809d>] do_sync_write+0x0/0x107
> [44307.765469]  [<c01789d9>] vfs_write+0x84/0x121
> [44307.765495]  [<c0178b0e>] sys_write+0x3c/0x63
> [44307.765525]  [<c010398a>] syscall_call+0x7/0xb
> [44307.765894]  =======================
> [44307.765894] ---[ end trace 2a0ce193654d04fb ]---
> [44307.884076] usb 4-2: new full speed USB device using uhci_hcd and
> address 3 [44308.017388] usb 4-2: device descriptor read/all, error -71
> [44308.026550] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.047000] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.056026] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.075044] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.090090] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.102860] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.117901] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.122647] usb 4-2: new full speed USB device using uhci_hcd and
> address 4 [44308.127745] EXT3-fs error (device dm-2): read_block_bitmap:
> Cannot read block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.136581] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.150331] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.159068] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.168617] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.185580] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.200611] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.204343] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.217310] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.228915] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.254557] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.270601] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.300419] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.301453] usb 4-2: string descriptor 0 read error: -71
> [44308.301572] usb 4-2: configuration #1 chosen from 1 choice
> [44308.308850] usb 4-2: can't set config #1, error -71
> [44308.308899] usb 4-2: New USB device found, idVendor=05e3, idProduct=0702
> [44308.308899] usb 4-2: New USB device strings: Mfr=0, Product=1,
> SerialNumber=0
> [44308.328418] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.336523] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.367727] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.384314] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.399502] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.423943] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.439201] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.450486] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.460527] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.464059] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.477362] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.498686] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.516538] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.520738] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.540687] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.557256] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.579235] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.590239] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.605335] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.628031] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44308.990689] EXT3-fs error (device dm-2): read_block_bitmap: Cannot read
> block bitmap - block_group = 966, block_bitmap = 31653888
> [44309.667656] Aborting journal on device dm-2.
> [44309.668659] __journal_remove_journal_head: freeing b_committed_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.668659] __journal_remove_journal_head: freeing b_frozen_data
> [44309.679137] ext3_abort called.
> [44309.679137] EXT3-fs error (device dm-2): ext3_journal_start_sb: Detected
> aborted journal
> [44309.679137] Remounting filesystem read-only
> [44338.161517] __ratelimit: 26116 messages suppressed
> [44338.161517] Buffer I/O error on device dm-2, logical block 8
> [44338.161517] lost page write due to I/O error on dm-2
> [44338.161517] Buffer I/O error on device dm-2, logical block 1027
> [44338.161517] lost page write due to I/O error on dm-2
> [44338.161517] Buffer I/O error on device dm-2, logical block 1539
> [44338.161517] lost page write due to I/O error on dm-2
> [44338.161531] Buffer I/O error on device dm-2, logical block 30998528
> [44338.161538] lost page write due to I/O error on dm-2
> [44338.162759] Buffer I/O error on device dm-2, logical block 30998529
> [44338.162767] lost page write due to I/O error on dm-2
> [44338.162776] Buffer I/O error on device dm-2, logical block 30998530
> [44338.162781] lost page write due to I/O error on dm-2
>
>
> This makes me feel that it might be a hardware issue.
>
> Ritesh

-- 
Ritesh Raj Sarraf
RESEARCHUT - http://www.researchut.com
"Necessity is the mother of invention."


[-- Attachment #1.2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 197 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]



^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [linux-pm] dm-crypt low performance
  2009-01-13 19:52       ` Ritesh Raj Sarraf
@ 2009-01-13 20:00         ` Alan Stern
  2009-01-19 10:34           ` [dm-devel] " Ritesh Raj Sarraf
  2009-01-19 10:34           ` [linux-pm] " Ritesh Raj Sarraf
  2009-01-13 20:00         ` Alan Stern
  1 sibling, 2 replies; 10+ messages in thread
From: Alan Stern @ 2009-01-13 20:00 UTC (permalink / raw)
  To: Ritesh Raj Sarraf; +Cc: device-mapper development, linux-pm, Milan Broz

On Wed, 14 Jan 2009, Ritesh Raj Sarraf wrote:

> Okay!! I think I now have the correct steps to reproduce it consistently.
...
> The above result is from a freshly booted linux with the same suspected faulty 
> USB HDD enclosure. I ran it on 2 kernels, one standard and one debug, and both 
> gave similar results.
> So shouldn't be faulty hardware.
> 
> 
> So then with my standard kernel, I booted + hibernated and then resumed and 
> then again ran the I/O. Here are the same results.
...
> So this seems to be happening on my laptop when the OS has used the 
> hibernation feature. I'm of-course doing a luksClose and USB device 
> disconnection before hibernation.

And presumably you reconnect the USB device after resuming.  That 
reconnect appears to be where the problem arises.

> Here's the usb device listing after hibernation/resume.
> 
> rrs@learner:~$ cat /tmp/lsusb.suspend
> Bus 005 Device 005: ID 046d:08c6 Logitech, Inc. QuickCam for DELL Notebooks
> Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> Bus 004 Device 007: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
> Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 001 Device 005: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
> Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub

Notice that the IDE Adapter is now attached to a 1.1 bus rather than a
2.0 bus.  That's why it's running so much slower.

> And here's the usb device listing after a fresh boot.
> 
> rrs@learner:~$ lsusb
> Bus 005 Device 004: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
> Bus 005 Device 003: ID 046d:08c6 Logitech, Inc. QuickCam for DELL Notebooks
> Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 001 Device 004: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
> Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub

Try building a kernel with CONFIG_USB_DEBUG enabled, and post the dmesg 
log showing what happens during the disconnect, hibernate, resume, and 
reconnect.

You could also try the same thing with no disconnect/reconnect.  Just 
leave the IDE adapter plugged in the whole time.

Alan Stern

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [dm-devel] dm-crypt low performance
  2009-01-13 19:52       ` Ritesh Raj Sarraf
  2009-01-13 20:00         ` [linux-pm] " Alan Stern
@ 2009-01-13 20:00         ` Alan Stern
  1 sibling, 0 replies; 10+ messages in thread
From: Alan Stern @ 2009-01-13 20:00 UTC (permalink / raw)
  To: Ritesh Raj Sarraf; +Cc: device-mapper development, linux-pm, Milan Broz

On Wed, 14 Jan 2009, Ritesh Raj Sarraf wrote:

> Okay!! I think I now have the correct steps to reproduce it consistently.
...
> The above result is from a freshly booted linux with the same suspected faulty 
> USB HDD enclosure. I ran it on 2 kernels, one standard and one debug, and both 
> gave similar results.
> So shouldn't be faulty hardware.
> 
> 
> So then with my standard kernel, I booted + hibernated and then resumed and 
> then again ran the I/O. Here are the same results.
...
> So this seems to be happening on my laptop when the OS has used the 
> hibernation feature. I'm of-course doing a luksClose and USB device 
> disconnection before hibernation.

And presumably you reconnect the USB device after resuming.  That 
reconnect appears to be where the problem arises.

> Here's the usb device listing after hibernation/resume.
> 
> rrs@learner:~$ cat /tmp/lsusb.suspend
> Bus 005 Device 005: ID 046d:08c6 Logitech, Inc. QuickCam for DELL Notebooks
> Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> Bus 004 Device 007: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
> Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 001 Device 005: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
> Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub

Notice that the IDE Adapter is now attached to a 1.1 bus rather than a
2.0 bus.  That's why it's running so much slower.

> And here's the usb device listing after a fresh boot.
> 
> rrs@learner:~$ lsusb
> Bus 005 Device 004: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
> Bus 005 Device 003: ID 046d:08c6 Logitech, Inc. QuickCam for DELL Notebooks
> Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 001 Device 004: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
> Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub

Try building a kernel with CONFIG_USB_DEBUG enabled, and post the dmesg 
log showing what happens during the disconnect, hibernate, resume, and 
reconnect.

You could also try the same thing with no disconnect/reconnect.  Just 
leave the IDE adapter plugged in the whole time.

Alan Stern

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [linux-pm] dm-crypt low performance
  2009-01-13 20:00         ` [linux-pm] " Alan Stern
  2009-01-19 10:34           ` [dm-devel] " Ritesh Raj Sarraf
@ 2009-01-19 10:34           ` Ritesh Raj Sarraf
  2009-01-19 16:23             ` [dm-devel] " Alan Stern
  1 sibling, 1 reply; 10+ messages in thread
From: Ritesh Raj Sarraf @ 2009-01-19 10:34 UTC (permalink / raw)
  To: Alan Stern; +Cc: device-mapper development, linux-pm, Milan Broz


[-- Attachment #1.1: Type: text/plain, Size: 2606 bytes --]

Hi Alan,


On Wednesday 14 Jan 2009 01:30:59 Alan Stern wrote:
> >
> > rrs@learner:~$ cat /tmp/lsusb.suspend
> > Bus 005 Device 005: ID 046d:08c6 Logitech, Inc. QuickCam for DELL
> > Notebooks Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> > Bus 004 Device 007: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
> > Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 001 Device 005: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
> > Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
>
> Notice that the IDE Adapter is now attached to a 1.1 bus rather than a
> 2.0 bus.  That's why it's running so much slower.
>
> > And here's the usb device listing after a fresh boot.
> >
> > rrs@learner:~$ lsusb
> > Bus 005 Device 004: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
> > Bus 005 Device 003: ID 046d:08c6 Logitech, Inc. QuickCam for DELL
> > Notebooks Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> > Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 001 Device 004: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
> > Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
>
> Try building a kernel with CONFIG_USB_DEBUG enabled, and post the dmesg
> log showing what happens during the disconnect, hibernate, resume, and
> reconnect.
>
> You could also try the same thing with no disconnect/reconnect.  Just
> leave the IDE adapter plugged in the whole time.
>

I've been testing the same hardware but unfortunately wasn't able to see the 
issue back again. One thing to notice is that the laptop has 4 USB ports out 
of which 3 are 1.1 and only 1 is 2.0.
The suspected faulty USB HDD Enclosure has 2 cables that I was connecting to, 
thus ending up connecting them to a 2.0 and 1.1 USB port.

I tried with just 1 port connected to USB 2.0 port and haven't been able to 
reproduce the issue back again yet. :-(
I also wasn't able to reproduce back the old issue with the pattern I 
mentioned in the previous post (1 cable connected to 1.1 and the other 
connected to 2.0 port)

I'll keep testing and post to this thread if I find something useful.

Thanks,
Ritesh
-- 
Ritesh Raj Sarraf
RESEARCHUT - http://www.researchut.com
"Necessity is the mother of invention."


[-- Attachment #1.2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 197 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]



^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [dm-devel] dm-crypt low performance
  2009-01-13 20:00         ` [linux-pm] " Alan Stern
@ 2009-01-19 10:34           ` Ritesh Raj Sarraf
  2009-01-19 10:34           ` [linux-pm] " Ritesh Raj Sarraf
  1 sibling, 0 replies; 10+ messages in thread
From: Ritesh Raj Sarraf @ 2009-01-19 10:34 UTC (permalink / raw)
  To: Alan Stern; +Cc: device-mapper development, linux-pm, Milan Broz


[-- Attachment #1.1: Type: text/plain, Size: 2606 bytes --]

Hi Alan,


On Wednesday 14 Jan 2009 01:30:59 Alan Stern wrote:
> >
> > rrs@learner:~$ cat /tmp/lsusb.suspend
> > Bus 005 Device 005: ID 046d:08c6 Logitech, Inc. QuickCam for DELL
> > Notebooks Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> > Bus 004 Device 007: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
> > Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 001 Device 005: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
> > Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
>
> Notice that the IDE Adapter is now attached to a 1.1 bus rather than a
> 2.0 bus.  That's why it's running so much slower.
>
> > And here's the usb device listing after a fresh boot.
> >
> > rrs@learner:~$ lsusb
> > Bus 005 Device 004: ID 05e3:0702 Genesys Logic, Inc. USB 2.0 IDE Adapter
> > Bus 005 Device 003: ID 046d:08c6 Logitech, Inc. QuickCam for DELL
> > Notebooks Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> > Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> > Bus 001 Device 004: ID 046d:c00c Logitech, Inc. Optical Wheel Mouse
> > Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
>
> Try building a kernel with CONFIG_USB_DEBUG enabled, and post the dmesg
> log showing what happens during the disconnect, hibernate, resume, and
> reconnect.
>
> You could also try the same thing with no disconnect/reconnect.  Just
> leave the IDE adapter plugged in the whole time.
>

I've been testing the same hardware but unfortunately wasn't able to see the 
issue back again. One thing to notice is that the laptop has 4 USB ports out 
of which 3 are 1.1 and only 1 is 2.0.
The suspected faulty USB HDD Enclosure has 2 cables that I was connecting to, 
thus ending up connecting them to a 2.0 and 1.1 USB port.

I tried with just 1 port connected to USB 2.0 port and haven't been able to 
reproduce the issue back again yet. :-(
I also wasn't able to reproduce back the old issue with the pattern I 
mentioned in the previous post (1 cable connected to 1.1 and the other 
connected to 2.0 port)

I'll keep testing and post to this thread if I find something useful.

Thanks,
Ritesh
-- 
Ritesh Raj Sarraf
RESEARCHUT - http://www.researchut.com
"Necessity is the mother of invention."


[-- Attachment #1.2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 197 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]



^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [dm-devel] dm-crypt low performance
  2009-01-19 10:34           ` [linux-pm] " Ritesh Raj Sarraf
@ 2009-01-19 16:23             ` Alan Stern
  0 siblings, 0 replies; 10+ messages in thread
From: Alan Stern @ 2009-01-19 16:23 UTC (permalink / raw)
  To: Ritesh Raj Sarraf; +Cc: device-mapper development, linux-pm, Milan Broz

On Mon, 19 Jan 2009, Ritesh Raj Sarraf wrote:

> I've been testing the same hardware but unfortunately wasn't able to see the 
> issue back again. One thing to notice is that the laptop has 4 USB ports out 
> of which 3 are 1.1 and only 1 is 2.0.
> The suspected faulty USB HDD Enclosure has 2 cables that I was connecting to, 
> thus ending up connecting them to a 2.0 and 1.1 USB port.

You should have mentioned this before!

One of those cables is for data and power, and the other cable is for 
power only (probably the thinner of the two).  For your drive to work 
correctly you should first plug in the power-only cable to a 1.1 port 
and then plug in the data/power cable to the 2.0 port.

If you mix things up and plug the data cable to a 1.1 port then of 
course the drive will operate only at 1.1 speed.

> I tried with just 1 port connected to USB 2.0 port and haven't been able to 
> reproduce the issue back again yet. :-(
> I also wasn't able to reproduce back the old issue with the pattern I 
> mentioned in the previous post (1 cable connected to 1.1 and the other 
> connected to 2.0 port)
> 
> I'll keep testing and post to this thread if I find something useful.

See if this doesn't clarify the matter.

Alan Stern

^ permalink raw reply	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2009-01-19 16:23 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2009-01-12 19:22 dm-crypt low performance Ritesh Raj Sarraf
     [not found] ` <0ths36-dce.ln1-b1aPebNLFEbkkoF7R9+BZ0EOCMrvLtNR@public.gmane.org>
2009-01-13 15:50   ` [dm-devel] " Milan Broz
2009-01-13 17:37     ` Ritesh Raj Sarraf
2009-01-13 19:52       ` Ritesh Raj Sarraf
2009-01-13 20:00         ` [linux-pm] " Alan Stern
2009-01-19 10:34           ` [dm-devel] " Ritesh Raj Sarraf
2009-01-19 10:34           ` [linux-pm] " Ritesh Raj Sarraf
2009-01-19 16:23             ` [dm-devel] " Alan Stern
2009-01-13 20:00         ` Alan Stern
2009-01-13 19:52       ` Ritesh Raj Sarraf

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.