Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S933290AbZIDJNI (ORCPT ); Fri, 4 Sep 2009 05:13:08 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S933083AbZIDJNF (ORCPT ); Fri, 4 Sep 2009 05:13:05 -0400 Received: from mail-fx0-f217.google.com ([209.85.220.217]:41469 "EHLO mail-fx0-f217.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S933031AbZIDJNB convert rfc822-to-8bit (ORCPT ); Fri, 4 Sep 2009 05:13:01 -0400 DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :cc:content-type:content-transfer-encoding; b=xDBwH7iI4RUdccdbYu0svw/x5yVuv3AuxM6VqTpjAV6wBjC66D5+J3sgD4k3MChB6L LN5wT0LKcJZ1P4c5p0/mPzTZShfTdqU1ka6ffPbqUSDCXSuQNObXcK9r4c5rsfOMLdku HGfhf4UebYB5XBVOe2Vzc9En178ieuLs7a6ww= MIME-Version: 1.0 In-Reply-To: <87ljkvmt71.fsf@devron.myhome.or.jp> References: <200908312119.12121.rjw@sisk.pl> <20090903232317.GA6760@lst.de> <87ljkvmt71.fsf@devron.myhome.or.jp> Date: Fri, 4 Sep 2009 11:13:02 +0200 Message-ID: Subject: Re: Regression in suspend to ram in 2.6.31-rc kernels From: Zdenek Kabelac To: OGAWA Hirofumi Cc: Christoph Hellwig , "Rafael J. Wysocki" , Linux Kernel Mailing List , linux-mmc@vger.kernel.org, viro@zeniv.linux.org.uk Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 8BIT Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 13442 Lines: 333 2009/9/4 OGAWA Hirofumi : > Christoph Hellwig writes: > >> On Fri, Sep 04, 2009 at 12:29:04AM +0200, Zdenek Kabelac wrote: >>> Ok - another bisect game played - and unexpected winner is: >>> >>> (fat: add ->sync_fs) >>> >>> f83d6d46e7adf241a064a4a425e5cd8a8fd8925f >>> >>> Reverting this commit with current -rc8 kernel makes the system happy >>> during the suspend/resume cycle. Obviously it has it price :) so just >>> plain revert is probably not a good solution so the problem looks >>> 'more serious' ?(fat is not the only fs with this patch) thus adding >>> original author to this thread. > > From it, I suspect the possible reason seems to read mmc after remove > event. I.e. the following sequence or something > > ? ?sync fs process > ? ?[...] > ? ?removed mmc event > ? ?[...] > ? ?fat_sync_fs() ? ? ? ? ? ? ? ? ? <- sync again? > ? ? ? ?fat_clusters_flush() > ? ? ? ? ? ?sb_bread() ? ? ? ? ? ? ?<- read block on removed mmc > > Can you add dump_stack() to the top of fat_sync_fs()? I hope it tells > why fat_sync_fs() is called (it is called from device unplug event?). > > Well, that commit seems a bit strange. It calls fat_clusters_flush() > unconditionally without checking sb->s_dirt. However, if my guess is > right, "sync after removed event" itself sounds like the issue in > suspend process. > > Thanks. > >> Note that when you rever this patch on a current kernel you do actually >> get different behvaviour than when going back to before this commit. >> >> In 2.6.30 we called ->write_super in the various sync functions and >> then ->sync_fs, in 2.6.31-rc8 you would not call any syncing at all >> anymore. ?I think this patch might just be a symptom for a situation >> where the suspend code causes a sync and the mmc driver can't handle >> it anymore. So - here is the console trace from suspend when I've added dump_stack() to the fat_sync_fs() (and also added debug prints around each call in this function -so its obvious the function is actually left - but then it freezes later somewhere.) It's interesting that 3 calls to sync happens. Zdenek usb 3-1: USB disconnect, address 2 btusb_intr_complete: hci0 urb ffff880137fdd630 failed to resubmit (19) btusb_bulk_complete: hci0 urb ffff880137fdd738 failed to resubmit (19) btusb_bulk_complete: hci0 urb ffff880137fdd840 failed to resubmit (19) PM: Removing info for No Bus:ep_81 PM: Removing info for No Bus:ep_82 PM: Removing info for No Bus:ep_02 PM: Removing info for usb:3-1:1.0 btusb_send_frame: hci0 urb ffff88013356b528 submission failed PM: Removing info for No Bus:rfkill0 PM: Removing info for No Bus:hci0 PM: Removing info for No Bus:ep_83 PM: Removing info for No Bus:ep_03 PM: Removing info for usb:3-1:1.1 PM: Removing info for No Bus:ep_84 PM: Removing info for No Bus:ep_04 PM: Removing info for usb:3-1:1.2 PM: Removing info for usb:3-1:1.3 PM: Removing info for No Bus:ep_00 PM: Removing info for usb:3-1 PM: Removing info for No Bus:usbdev3.2 PM: Adding info for No Bus:vcs63 PM: Adding info for No Bus:vcsa63 FAT: dump before lock Pid: 2271, comm: sync Not tainted 2.6.31-rc8-00043-g54a3792 #32 Call Trace: [] fat_sync_fs+0x24/0x80 [fat] [] __sync_filesystem+0x36/0x50 [] sync_filesystems+0xf8/0x130 [] sys_sync+0x17/0x40 [] system_call_fastpath+0x16/0x1b FAT: fat_cluster_flush FAT: before unlock FAT: leaving fat_sync_fs FAT: dump before lock Pid: 2271, comm: sync Not tainted 2.6.31-rc8-00043-g54a3792 #32 Call Trace: [] fat_sync_fs+0x24/0x80 [fat] [] __sync_filesystem+0x36/0x50 [] sync_filesystems+0xf8/0x130 [] sys_sync+0x21/0x40 [] system_call_fastpath+0x16/0x1b FAT: fat_cluster_flush FAT: before unlock FAT: leaving fat_sync_fs PM: Removing info for No Bus:iwl-phy0::assoc PM: Syncing filesystems ... FAT: dump before lock Pid: 2143, comm: pm-suspend Not tainted 2.6.31-rc8-00043-g54a3792 #32 Call Trace: [] fat_sync_fs+0x24/0x80 [fat] [] __sync_filesystem+0x36/0x50 [] sync_filesystems+0xf8/0x130 [] sys_sync+0x17/0x40 [] enter_state+0x6b/0x150 [] state_store+0x99/0x100 [] kobj_attr_store+0x17/0x20 [] sysfs_write_file+0xd9/0x160 [] vfs_write+0xb8/0x1a0 [] ? audit_syscall_entry+0x28b/0x2b0 [] sys_write+0x51/0x90 [] system_call_fastpath+0x16/0x1b FAT: fat_cluster_flush FAT: before unlock FAT: leaving fat_sync_fs PM: Removing info for No Bus:iwl-phy0::RX PM: Removing info for No Bus:iwl-phy0::TX PM: Removing info for No Bus:iwl-phy0::radio FAT: dump before lock Pid: 2143, comm: pm-suspend Not tainted 2.6.31-rc8-00043-g54a3792 #32 Call Trace: [] fat_sync_fs+0x24/0x80 [fat] [] __sync_filesystem+0x36/0x50 [] sync_filesystems+0xf8/0x130 [] sys_sync+0x21/0x40 [] enter_state+0x6b/0x150 [] state_store+0x99/0x100 [] kobj_attr_store+0x17/0x20 [] sysfs_write_file+0xd9/0x160 [] vfs_write+0xb8/0x1a0 [] ? audit_syscall_entry+0x28b/0x2b0 [] sys_write+0x51/0x90 [] system_call_fastpath+0x16/0x1b FAT: fat_cluster_flush FAT: before unlock FAT: leaving fat_sync_fs done. PM: Preparing system for mem sleep Freezing user space processes ... (elapsed 0.00 seconds) done. Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. PM: Entering mem sleep platform dock.0: preparing suspend platform dock.1: preparing suspend platform dock.2: preparing suspend agpgart-intel 0000:00:00.0: preparing suspend pci 0000:00:02.0: preparing suspend pci 0000:00:02.1: preparing suspend e1000e 0000:00:19.0: preparing suspend, may wakeup uhci_hcd 0000:00:1a.0: preparing suspend uhci_hcd 0000:00:1a.1: preparing suspend ehci_hcd 0000:00:1a.7: preparing suspend HDA Intel 0000:00:1b.0: preparing suspend pcieport-driver 0000:00:1c.0: preparing suspend pcieport-driver 0000:00:1c.1: preparing suspend pcieport-driver 0000:00:1c.2: preparing suspend pcieport-driver 0000:00:1c.3: preparing suspend pcieport-driver 0000:00:1c.4: preparing suspend uhci_hcd 0000:00:1d.0: preparing suspend uhci_hcd 0000:00:1d.1: preparing suspend uhci_hcd 0000:00:1d.2: preparing suspend ehci_hcd 0000:00:1d.7: preparing suspend pci 0000:00:1e.0: preparing suspend pci 0000:00:1f.0: preparing suspend ata_piix 0000:00:1f.1: preparing suspend ahci 0000:00:1f.2: preparing suspend i801_smbus 0000:00:1f.3: preparing suspend iwl3945 0000:03:00.0: preparing suspend pci 0000:15:00.0: preparing suspend sdhci-pci 0000:15:00.2: preparing suspend pci 0000:15:00.3: preparing suspend pci 0000:15:00.4: preparing suspend pci 0000:15:00.5: preparing suspend platform vesafb.0: preparing suspend serial8250 serial8250: preparing suspend i8042 i8042: preparing suspend platform hdaps: preparing suspend usb usb1: preparing type suspend, may wakeup usb usb2: preparing type suspend, may wakeup usb usb3: preparing type suspend, may wakeup usb usb4: preparing type suspend, may wakeup usb usb5: preparing type suspend, may wakeup usb usb6: preparing type suspend, may wakeup usb usb7: preparing type suspend, may wakeup usb 1-4: preparing type suspend, may wakeup usb 3-2: preparing type suspend, may wakeup usb 1-4.4: preparing type suspend, may wakeup iTCO_wdt iTCO_wdt: preparing suspend platform regulatory.0: preparing suspend thinkpad_acpi thinkpad_acpi: preparing suspend thinkpad_hwmon thinkpad_hwmon: preparing suspend backlight acpi_video0: legacy class suspend drm card0: legacy class suspend pci 0000:00:02.0: power state changed by ACPI to D3 mmcblk mmc0:b368: legacy suspend leds mmc0::: legacy class suspend rfkill rfkill2: legacy class suspend ieee80211 phy0: legacy class suspend leds tpacpi::thinkvantage: legacy class suspend leds tpacpi::standby: legacy class suspend leds tpacpi::power: legacy class suspend leds tpacpi::thinklight: legacy class suspend rfkill rfkill1: legacy class suspend thinkpad_hwmon thinkpad_hwmon: suspend thinkpad_acpi thinkpad_acpi: suspend psmouse serio2: legacy suspend platform regulatory.0: suspend iTCO_wdt iTCO_wdt: suspend usb 1-4.4: type suspend, may wakeup usb 3-2: type suspend, may wakeup usb 1-4: type suspend, may wakeup usb usb7: type suspend, may wakeup usb usb6: type suspend, may wakeup usb usb5: type suspend, may wakeup usb usb4: type suspend, may wakeup usb usb3: type suspend, may wakeup usb usb2: type suspend, may wakeup usb usb1: type suspend, may wakeup sr 3:0:0:0: legacy suspend scsi target3:0:0: legacy suspend sd 0:0:0:0: legacy suspend sd 0:0:0:0: [sda] Synchronizing SCSI cache sd 0:0:0:0: [sda] Stopping disk scsi target0:0:0: legacy suspend platform hdaps: suspend psmouse serio1: legacy suspend atkbd serio0: legacy suspend i8042 i8042: suspend scsi host4: legacy suspend scsi host3: legacy suspend scsi host2: legacy suspend scsi host1: legacy suspend scsi host0: legacy suspend serial8250 serial8250: suspend platform vesafb.0: suspend pnp 00:0a: legacy suspend i8042 aux 00:09: legacy suspend i8042 kbd 00:08: legacy suspend rtc_cmos 00:07: legacy suspend, may wakeup pnp 00:06: legacy suspend pnp 00:05: legacy suspend pnp 00:04: legacy suspend pnp 00:03: legacy suspend system 00:02: legacy suspend pnp 00:01: legacy suspend system 00:00: legacy suspend pci 0000:15:00.5: suspend pci 0000:15:00.4: suspend pci 0000:15:00.3: suspend sdhci-pci 0000:15:00.2: suspend mmc0: card b368 removed PM: Removing info for mmc:mmc0:b368 FAT: dump before lock Pid: 2143, comm: pm-suspend Not tainted 2.6.31-rc8-00043-g54a3792 #32 Call Trace: [] fat_sync_fs+0x24/0x80 [fat] [] __sync_filesystem+0x36/0x50 [] sync_filesystem+0x3a/0x70 [] fsync_bdev+0x2e/0x70 [] invalidate_partition+0x2e/0x50 [] del_gendisk+0x3f/0x140 [] mmc_blk_remove+0x2e/0x60 [mmc_block] [] mmc_bus_remove+0x17/0x20 [mmc_core] [] __device_release_driver+0x66/0xc0 [] device_release_driver+0x2d/0x40 [] bus_remove_device+0xac/0xe0 [] device_del+0x12f/0x1a0 [] mmc_remove_card+0x5b/0x90 [mmc_core] [] mmc_sd_remove+0x27/0x50 [mmc_core] [] mmc_suspend_host+0xed/0x120 [mmc_core] [] sdhci_suspend_host+0x38/0x60 [sdhci] [] sdhci_pci_suspend+0x50/0x130 [sdhci_pci] [] pci_legacy_suspend+0x4d/0xf0 [] pci_pm_suspend+0xdd/0x130 [] pm_op+0x15b/0x1b0 [] dpm_suspend_start+0x423/0x580 [] suspend_devices_and_enter+0x5f/0x1d0 [] enter_state+0x128/0x150 [] state_store+0x99/0x100 [] kobj_attr_store+0x17/0x20 [] sysfs_write_file+0xd9/0x160 [] vfs_write+0xb8/0x1a0 [] ? audit_syscall_entry+0x28b/0x2b0 [] sys_write+0x51/0x90 [] system_call_fastpath+0x16/0x1b FAT: fat_cluster_flush FAT: before unlock FAT: leaving fat_sync_fs FAT: dump before lock Pid: 2143, comm: pm-suspend Not tainted 2.6.31-rc8-00043-g54a3792 #32 Call Trace: [] fat_sync_fs+0x24/0x80 [fat] [] __sync_filesystem+0x36/0x50 [] sync_filesystem+0x4b/0x70 [] fsync_bdev+0x2e/0x70 [] invalidate_partition+0x2e/0x50 [] del_gendisk+0x3f/0x140 [] mmc_blk_remove+0x2e/0x60 [mmc_block] [] mmc_bus_remove+0x17/0x20 [mmc_core] [] __device_release_driver+0x66/0xc0 [] device_release_driver+0x2d/0x40 [] bus_remove_device+0xac/0xe0 [] device_del+0x12f/0x1a0 [] mmc_remove_card+0x5b/0x90 [mmc_core] [] mmc_sd_remove+0x27/0x50 [mmc_core] [] mmc_suspend_host+0xed/0x120 [mmc_core] [] sdhci_suspend_host+0x38/0x60 [sdhci] [] sdhci_pci_suspend+0x50/0x130 [sdhci_pci] [] pci_legacy_suspend+0x4d/0xf0 [] pci_pm_suspend+0xdd/0x130 [] pm_op+0x15b/0x1b0 [] dpm_suspend_start+0x423/0x580 [] suspend_devices_and_enter+0x5f/0x1d0 [] enter_state+0x128/0x150 [] state_store+0x99/0x100 [] kobj_attr_store+0x17/0x20 [] sysfs_write_file+0xd9/0x160 [] vfs_write+0xb8/0x1a0 [] ? audit_syscall_entry+0x28b/0x2b0 [] sys_write+0x51/0x90 [] system_call_fastpath+0x16/0x1b FAT: fat_cluster_flush FAT: before unlock FAT: leaving fat_sync_fs -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/