From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756761AbZEZTOl (ORCPT ); Tue, 26 May 2009 15:14:41 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1755732AbZEZTOc (ORCPT ); Tue, 26 May 2009 15:14:32 -0400 Received: from mail-bw0-f222.google.com ([209.85.218.222]:47015 "EHLO mail-bw0-f222.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752402AbZEZTOa (ORCPT ); Tue, 26 May 2009 15:14:30 -0400 DomainKey-Signature: a=rsa-sha1; c=nofws; d=googlemail.com; s=gamma; h=mime-version:date:message-id:subject:from:to:cc:content-type :content-transfer-encoding; b=tHqxTzGZMjUi0O8osEFsyqsXRL+TmTSVFd+oDOiQSxBT9K7lGFde8kT66NfaYeQzdv d5tehDLanWpskg9dqXr2u99CeJlssWttXH2rMIZcF6a1swNsvdzS8vbFheZRVGA2SmZO uFqg6y/16y6M+47tNJyu9MV+F9tYk+QlfPtGM= MIME-Version: 1.0 Date: Tue, 26 May 2009 21:14:29 +0200 Message-ID: <64bb37e0905261214g2957924ar837339367f320d4c@mail.gmail.com> Subject: sata_sil24 0000:04:00.0: DMA-API: device driver frees DMA sg list with different entry count [map count=13] [unmap count=10] From: Torsten Kaiser To: Linux Kernel Mailing List Cc: SCSI development list Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On upgrading to 2.6.30-rc1 I enable the DMA-Debugging option CONFIG_DMA_API_DEBUG=y Since then I get the following or similar errors on each boot: May 26 06:50:31 treogen [ 231.082923] ------------[ cut here ]------------ May 26 06:50:31 treogen [ 231.082942] WARNING: at lib/dma-debug.c:530 check_unmap+0x65e/0x6a0() May 26 06:50:31 treogen [ 231.082947] Hardware name: KFN5-D SLI May 26 06:50:31 treogen [ 231.082952] sata_sil24 0000:04:00.0: DMA-API: device driver frees DMA sg list with different entry count [map count=13] [unmap count=10] May 26 06:50:31 treogen [ 231.082958] Modules linked in: msp3400 tuner tea5767 tda8290 tuner_xc2028 xc5000 tda9887 tuner_simple tuner_types mt20xx tea5761 bttv ir_common v4l2_common videodev v4l1_compat v4l2_compat_ioctl32 videobuf_dma_sg videobuf_core sg pata_amd btcx_risc tveeprom May 26 06:50:31 treogen [ 231.083000] Pid: 3575, comm: logger Not tainted 2.6.30-rc7 #1 May 26 06:50:31 treogen [ 231.083005] Call Trace: May 26 06:50:31 treogen [ 231.083009] [] ? check_unmap+0x65e/0x6a0 May 26 06:50:31 treogen [ 231.083026] [] warn_slowpath_common+0x78/0xd0 May 26 06:50:31 treogen [ 231.083033] [] warn_slowpath_fmt+0x64/0x70 May 26 06:50:31 treogen [ 231.083043] [] ? mempool_free_slab+0x12/0x20 May 26 06:50:31 treogen [ 231.083054] [] ? _spin_lock_irqsave+0x1d/0x40 May 26 06:50:31 treogen [ 231.083061] [] check_unmap+0x65e/0x6a0 May 26 06:50:31 treogen [ 231.083068] [] debug_dma_unmap_sg+0x10e/0x1b0 May 26 06:50:31 treogen [ 231.083077] [] ? __scsi_put_command+0x61/0xa0 May 26 06:50:31 treogen [ 231.083086] [] ata_sg_clean+0x78/0xf0 May 26 06:50:31 treogen [ 231.083093] [] __ata_qc_complete+0x35/0x110 May 26 06:50:31 treogen [ 231.083101] [] ? scsi_io_completion+0x398/0x530 May 26 06:50:31 treogen [ 231.083108] [] ata_qc_complete+0xbd/0x250 May 26 06:50:31 treogen [ 231.083116] [] ata_qc_complete_multiple+0xab/0xf0 May 26 06:50:31 treogen [ 231.083125] [] sil24_interrupt+0xb9/0x5b0 May 26 06:50:31 treogen [ 231.083133] [] handle_IRQ_event+0x70/0x180 May 26 06:50:31 treogen [ 231.083140] [] handle_fasteoi_irq+0x6d/0xe0 May 26 06:50:31 treogen [ 231.083147] [] handle_irq+0x1f/0x30 May 26 06:50:31 treogen [ 231.083153] [] do_IRQ+0x6a/0xf0 May 26 06:50:31 treogen [ 231.083162] [] ret_from_intr+0x0/0xf May 26 06:50:31 treogen [ 231.083166] [] ? _spin_unlock_irqrestore+0x1a/0x40 May 26 06:50:31 treogen [ 231.083179] [] ? __up_read+0x91/0xb0 May 26 06:50:31 treogen [ 231.083188] [] ? up_read+0x9/0x10 May 26 06:50:31 treogen [ 231.083196] [] ? do_page_fault+0x147/0x280 May 26 06:50:31 treogen [ 231.083204] [] ? page_fault+0x1f/0x30 May 26 06:50:31 treogen [ 231.083209] ---[ end trace 9d69801031c35329 ]--- May 26 06:50:31 treogen [ 231.083213] Mapped at: May 26 06:50:31 treogen [ 231.083215] [] debug_dma_map_sg+0x159/0x180 May 26 06:50:31 treogen [ 231.083224] [] ata_qc_issue+0x19c/0x300 May 26 06:50:31 treogen [ 231.083231] [] ata_scsi_translate+0xa8/0x180 May 26 06:50:31 treogen [ 231.083239] [] ata_scsi_queuecmd+0xb1/0x2d0 May 26 06:50:31 treogen [ 231.083245] [] scsi_dispatch_cmd+0xe3/0x220 Other traces: One with a size mismatch instead of the wrong map count: May 26 19:16:55 treogen [ 131.688242] ------------[ cut here ]------------ May 26 19:16:55 treogen [ 131.688262] WARNING: at lib/dma-debug.c:505 check_unmap+0x455/0x6a0() May 26 19:16:55 treogen [ 131.688267] Hardware name: KFN5-D SLI May 26 19:16:55 treogen [ 131.688273] sata_sil24 0000:04:00.0: DMA-API: device driver frees DMA memory with different size [device address=0x0000000078886000] [map size=8192 bytes] [unmap size=16384 bytes] May 26 19:16:55 treogen [ 131.688280] Modules linked in: msp3400 tuner tea5767 tda8290 tuner_xc2028 xc 5000 tda9887 tuner_simple tuner_types mt20xx tea5761 bttv ir_common v4l2_common videodev v4l1_compat v4 l2_compat_ioctl32 videobuf_dma_sg videobuf_core btcx_risc tveeprom sg pata_amd May 26 19:16:55 treogen [ 131.688322] Pid: 0, comm: swapper Not tainted 2.6.30-rc7 #1 May 26 19:16:55 treogen [ 131.688327] Call Trace: May 26 19:16:55 treogen [ 131.688331] [] ? check_unmap+0x455/0x6a0 May 26 19:16:55 treogen [ 131.688348] [] warn_slowpath_common+0x78/0xd0 May 26 19:16:55 treogen [ 131.688355] [] warn_slowpath_fmt+0x64/0x70 May 26 19:16:55 treogen [ 131.688366] [] ? mempool_free_slab+0x12/0x20 May 26 19:16:55 treogen [ 131.688376] [] ? _spin_lock_irqsave+0x1d/0x40 May 26 19:16:55 treogen [ 131.688384] [] check_unmap+0x455/0x6a0 May 26 19:16:55 treogen [ 131.688391] [] debug_dma_unmap_sg+0x10e/0x1b0 May 26 19:16:55 treogen [ 131.688400] [] ? __scsi_put_command+0x61/0xa0 May 26 19:16:55 treogen [ 131.688410] [] ata_sg_clean+0x78/0xf0 May 26 19:16:55 treogen [ 131.688417] [] __ata_qc_complete+0x35/0x110 May 26 19:16:55 treogen [ 131.688426] [] ? scsi_io_completion+0x398/0x530 May 26 19:16:55 treogen [ 131.688433] [] ata_qc_complete+0xbd/0x250 May 26 19:16:55 treogen [ 131.688441] [] ata_qc_complete_multiple+0xab/0xf0 May 26 19:16:55 treogen [ 131.688450] [] sil24_interrupt+0xb9/0x5b0 May 26 19:16:55 treogen [ 131.688457] [] ? getnstimeofday+0x5c/0xf0 May 26 19:16:55 treogen [ 131.688466] [] ? ktime_get_ts+0x59/0x60 May 26 19:16:55 treogen [ 131.688474] [] handle_IRQ_event+0x70/0x180 May 26 19:16:55 treogen [ 131.688482] [] handle_fasteoi_irq+0x6d/0xe0 May 26 19:16:55 treogen [ 131.688489] [] handle_irq+0x1f/0x30 May 26 19:16:55 treogen [ 131.688495] [] do_IRQ+0x6a/0xf0 May 26 19:16:55 treogen [ 131.688504] [] ret_from_intr+0x0/0xf May 26 19:16:55 treogen [ 131.688508] [] ? default_idle+0x77/0xe0 May 26 19:16:55 treogen [ 131.688522] [] ? default_idle+0x75/0xe0 May 26 19:16:55 treogen [ 131.688529] [] ? notifier_call_chain+0x3f/0x80 May 26 19:16:55 treogen [ 131.688536] [] ? c1e_idle+0x38/0x110 May 26 19:16:55 treogen [ 131.688544] [] ? cpu_idle+0x6e/0xd0 May 26 19:16:55 treogen [ 131.688553] [] ? rest_init+0x6d/0x80 May 26 19:16:55 treogen [ 131.688562] [] ? start_kernel+0x35a/0x422 May 26 19:16:55 treogen [ 131.688570] [] ? x86_64_start_reservations+0x99/0xb9 May 26 19:16:55 treogen [ 131.688577] [] ? x86_64_start_kernel+0xe0/0xf2 May 26 19:16:55 treogen [ 131.688582] ---[ end trace cff6b5339db27b54 ]--- May 26 19:16:55 treogen [ 131.688585] Mapped at: May 26 19:16:55 treogen [ 131.688588] [] debug_dma_map_sg+0x159/0x180 May 26 19:16:55 treogen [ 131.688597] [] ata_qc_issue+0x19c/0x300 May 26 19:16:55 treogen [ 131.688604] [] ata_scsi_translate+0xa8/0x180 May 26 19:16:55 treogen [ 131.688613] [] ata_scsi_queuecmd+0xb1/0x2d0 May 26 19:16:55 treogen [ 131.688619] [] scsi_dispatch_cmd+0xe3/0x220 sometimes the "Mapped at" info is missing: May 23 03:57:55 treogen [ 70.774289] ------------[ cut here ]------------ May 23 03:57:55 treogen [ 70.774297] WARNING: at lib/dma-debug.c:530 check_unmap+0x65e/0x6a0() May 23 03:57:55 treogen [ 70.774302] Hardware name: KFN5-D SLI May 23 03:57:55 treogen [ 70.774307] sata_sil24 0000:04:00.0: DMA-API: device driver frees DMA sg lis t with different entry count [map count=4] [unmap count=2] May 23 03:57:55 treogen [ 70.774313] Modules linked in: msp3400 tuner tea5767 tda8290 tuner_xc2028 xc 5000 tda9887 tuner_simple tuner_types mt20xx tea5761 bttv ir_common v4l2_common videodev v4l1_compat v4 l2_compat_ioctl32 videobuf_dma_sg videobuf_core btcx_risc tveeprom pata_amd sg May 23 03:57:55 treogen [ 70.774355] Pid: 458, comm: xfslogd/3 Not tainted 2.6.30-rc6 #1 May 23 03:57:55 treogen [ 70.774359] Call Trace: May 23 03:57:55 treogen [ 70.774363] [] warn_slowpath_fmt+0xd0/0x120 May 23 03:57:55 treogen [ 70.774383] [] ? dump_trace+0x116/0x2c0 May 23 03:57:55 treogen [ 70.774395] [] ? _spin_unlock_irqrestore+0x2f/0x40 May 23 03:57:55 treogen [ 70.774402] [] ? add_dma_entry+0x64/0x80 May 23 03:57:55 treogen [ 70.774413] [] ? sil24_qc_prep+0xb0/0x150 May 23 03:57:55 treogen [ 70.774422] [] ? ata_qc_issue+0x1e5/0x300 May 23 03:57:55 treogen [ 70.774430] [] ? scsi_done+0x0/0x20 May 23 03:57:55 treogen [ 70.774438] [] ? ata_scsi_rw_xlat+0x0/0x210 May 23 03:57:55 treogen [ 70.774445] [] ? ata_scsi_translate+0xa8/0x180 May 23 03:57:55 treogen [ 70.774452] [] check_unmap+0x65e/0x6a0 May 23 03:57:55 treogen [ 70.774459] [] debug_dma_unmap_sg+0x10e/0x1b0 May 23 03:57:55 treogen [ 70.774467] [] ? __scsi_put_command+0x61/0xa0 May 23 03:57:55 treogen [ 70.774474] [] ata_sg_clean+0x78/0xf0 May 23 03:57:55 treogen [ 70.774480] [] __ata_qc_complete+0x35/0x110 May 23 03:57:55 treogen [ 70.774489] [] ? scsi_io_completion+0x398/0x530 May 23 03:57:55 treogen [ 70.774496] [] ata_qc_complete+0xbd/0x250 May 23 03:57:55 treogen [ 70.774503] [] ata_qc_complete_multiple+0xab/0xf0 May 23 03:57:55 treogen [ 70.774510] [] sil24_interrupt+0xb9/0x5a0 May 23 03:57:55 treogen [ 70.774520] [] handle_IRQ_event+0x70/0x180 May 23 03:57:55 treogen [ 70.774527] [] handle_fasteoi_irq+0x6d/0xe0 May 23 03:57:55 treogen [ 70.774533] [] handle_irq+0x1f/0x30 May 23 03:57:55 treogen [ 70.774538] [] do_IRQ+0x6a/0xf0 May 23 03:57:55 treogen [ 70.774547] [] ret_from_intr+0x0/0xf May 23 03:57:55 treogen [ 70.774551] [] ? finish_task_switch+0x54/0x100 May 23 03:57:55 treogen [ 70.774566] [] ? cfq_kick_queue+0x0/0x40 May 23 03:57:55 treogen [ 70.774573] [] ? thread_return+0x3e/0x6f7 May 23 03:57:55 treogen [ 70.774582] [] ? xfs_buf_iodone_work+0x0/0xa0 May 23 03:57:55 treogen [ 70.774589] [] ? xfs_buf_iodone_work+0x0/0xa0 May 23 03:57:55 treogen [ 70.774595] [] ? schedule+0x9/0x20 May 23 03:57:55 treogen [ 70.774604] [] ? worker_thread+0x1e5/0x1f0 May 23 03:57:55 treogen [ 70.774612] [] ? autoremove_wake_function+0x0/0x40 May 23 03:57:55 treogen [ 70.774620] [] ? worker_thread+0x0/0x1f0 May 23 03:57:55 treogen [ 70.774627] [] ? worker_thread+0x0/0x1f0 May 23 03:57:55 treogen [ 70.774633] [] ? kthread+0x56/0x90 May 23 03:57:55 treogen [ 70.774641] [] ? child_rip+0xa/0x20 May 23 03:57:55 treogen [ 70.774648] [] ? restore_args+0x0/0x30 May 23 03:57:55 treogen [ 70.774654] [] ? kthread+0x0/0x90 May 23 03:57:55 treogen [ 70.774661] [] ? child_rip+0x0/0x20 May 23 03:57:55 treogen [ 70.774665] ---[ end trace 65ea6e90ae7ed767 ]--- May 23 03:57:55 treogen [ 70.774669] Mapped at: May 23 03:57:55 treogen [ 70.774672] [] 0xffffffffffffffff It is also not at the same time of each boot, once it took really long to show up: May 24 15:50:24 treogen [25330.655309] ------------[ cut here ]------------ May 24 15:50:24 treogen [25330.655327] WARNING: at lib/dma-debug.c:530 check_unmap+0x65e/0x6a0() May 24 15:50:24 treogen [25330.655331] Hardware name: KFN5-D SLI May 24 15:50:24 treogen [25330.655337] sata_sil24 0000:04:00.0: DMA-API: device driver frees DMA sg lis t with different entry count [map count=2] [unmap count=1] May 24 15:50:24 treogen [25330.655342] Modules linked in: msp3400 tuner tea5767 tda8290 tuner_xc2028 xc 5000 tda9887 tuner_simple tuner_types mt20xx tea5761 bttv ir_common v4l2_common videodev v4l1_compat v4 l2_compat_ioctl32 videobuf_dma_sg videobuf_core btcx_risc sg tveeprom pata_amd May 24 15:50:24 treogen [25330.655384] Pid: 0, comm: swapper Not tainted 2.6.30-rc7 #1 May 24 15:50:24 treogen [25330.655388] Call Trace: May 24 15:50:24 treogen [25330.655392] [] ? check_unmap+0x65e/0x6a0 May 24 15:50:24 treogen [25330.655408] [] warn_slowpath_common+0x78/0xd0 May 24 15:50:24 treogen [25330.655415] [] warn_slowpath_fmt+0x64/0x70 May 24 15:50:24 treogen [25330.655425] [] ? mempool_free+0x8a/0xa0 May 24 15:50:24 treogen [25330.655432] [] ? mempool_free_slab+0x12/0x20 May 24 15:50:24 treogen [25330.655442] [] ? _spin_lock_irqsave+0x1d/0x40 May 24 15:50:24 treogen [25330.655449] [] check_unmap+0x65e/0x6a0 May 24 15:50:24 treogen [25330.655457] [] debug_dma_unmap_sg+0x10e/0x1b0 May 24 15:50:24 treogen [25330.655465] [] ? __slab_free+0x185/0x340 May 24 15:50:24 treogen [25330.655474] [] ? __scsi_put_command+0x61/0xa0 May 24 15:50:24 treogen [25330.655483] [] ata_sg_clean+0x78/0xf0 May 24 15:50:24 treogen [25330.655490] [] __ata_qc_complete+0x35/0x110 May 24 15:50:24 treogen [25330.655499] [] ? scsi_io_completion+0x398/0x530 May 24 15:50:24 treogen [25330.655506] [] ata_qc_complete+0xbd/0x250 May 24 15:50:24 treogen [25330.655513] [] ata_qc_complete_multiple+0xab/0xf0 May 24 15:50:24 treogen [25330.655522] [] sil24_interrupt+0xb9/0x5b0 May 24 15:50:24 treogen [25330.655529] [] ? getnstimeofday+0x5c/0xf0 May 24 15:50:24 treogen [25330.655538] [] ? ktime_get_ts+0x59/0x60 May 24 15:50:24 treogen [25330.655546] [] handle_IRQ_event+0x70/0x180 May 24 15:50:24 treogen [25330.655553] [] handle_fasteoi_irq+0x6d/0xe0 May 24 15:50:24 treogen [25330.655561] [] handle_irq+0x1f/0x30 May 24 15:50:24 treogen [25330.655566] [] do_IRQ+0x6a/0xf0 May 24 15:50:24 treogen [25330.655575] [] ret_from_intr+0x0/0xf May 24 15:50:24 treogen [25330.655579] [] ? default_idle+0x77/0xe0 May 24 15:50:24 treogen [25330.655592] [] ? default_idle+0x75/0xe0 May 24 15:50:24 treogen [25330.655600] [] ? notifier_call_chain+0x3f/0x80 May 24 15:50:24 treogen [25330.655607] [] ? c1e_idle+0x38/0x110 May 24 15:50:24 treogen [25330.655614] [] ? cpu_idle+0x6e/0xd0 May 24 15:50:24 treogen [25330.655623] [] ? rest_init+0x6d/0x80 May 24 15:50:24 treogen [25330.655632] [] ? start_kernel+0x35a/0x422 May 24 15:50:24 treogen [25330.655639] [] ? x86_64_start_reservations+0x99/0xb9 May 24 15:50:24 treogen [25330.655646] [] ? x86_64_start_kernel+0xe0/0xf2 May 24 15:50:24 treogen [25330.655651] ---[ end trace 513a0b087125ae17 ]--- May 24 15:50:24 treogen [25330.655655] Mapped at: May 24 15:50:24 treogen [25330.655658] [] debug_dma_map_sg+0x159/0x180 May 24 15:50:24 treogen [25330.655666] [] ata_qc_issue+0x19c/0x300 May 24 15:50:24 treogen [25330.655674] [] ata_scsi_translate+0xa8/0x180 May 24 15:50:24 treogen [25330.655682] [] ata_scsi_queuecmd+0xb1/0x2d0 May 24 15:50:24 treogen [25330.655688] [] scsi_dispatch_cmd+0xe3/0x220 The system in an AMD x86_64 with 4GB of RAM, some of it remapped to above the 32bit address limit. lspci from the controller in question: 04:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01) Subsystem: ASUSTeK Computer Inc. Device 819f Flags: bus master, fast devsel, latency 0, IRQ 19 Memory at efeffc00 (64-bit, non-prefetchable) [size=128] Memory at efef8000 (64-bit, non-prefetchable) [size=16K] I/O ports at ec00 [size=128] Expansion ROM at efe00000 [disabled] [size=512K] Capabilities: [54] Power Management version 2 Capabilities: [5c] MSI: Mask- 64bit+ Count=1/1 Enable- Capabilities: [70] Express Legacy Endpoint, MSI 00 Kernel driver in use: sata_sil24 Looking at the code in libata I can't see any problems with qc->orig_n_elem, so I have no clue what goes wrong here. If you need more information, please ask. Torsten