Search Results

Search found 130 results on 6 pages for 'kern'.

Page 6/6 | < Previous Page | 2 3 4 5 6 

• Why does my laptop resume immediately after suspend?

  - by Igor Zinov'yev

  I seem to be having some problem with suspend mode. Every time I try to suspend my laptop, it just locks the screen. Or maybe it successfully suspends just to resume only an instant after. What could cause such a behaviour? I'm running 32-bit Ubuntu 12.04 with the 3.2.0-25 kernel on a HP dv5-1178er Pavilion laptop (Intel Core 2 Duo). Here are the relevant log sections: kern.log: Jun 1 10:42:21 igor-laptop kernel: [ 2225.131171] PM: Syncing filesystems ... done. Jun 1 10:42:21 igor-laptop kernel: [ 2225.141222] PM: Preparing system for mem sleep Jun 1 10:42:21 igor-laptop kernel: [ 2225.141239] Freezing user space processes ... (elapsed 0.01 seconds) done. Jun 1 10:42:21 igor-laptop kernel: [ 2225.156171] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done. Jun 1 10:42:21 igor-laptop kernel: [ 2225.172139] PM: Entering mem sleep Jun 1 10:42:21 igor-laptop kernel: [ 2225.172169] Suspending console(s) (use no_console_suspend to debug) Jun 1 10:42:21 igor-laptop kernel: [ 2225.172895] sd 0:0:0:0: [sda] Synchronizing SCSI cache Jun 1 10:42:21 igor-laptop kernel: [ 2225.181767] sd 0:0:0:0: [sda] Stopping disk Jun 1 10:42:21 igor-laptop kernel: [ 2225.251089] ene_ir 00:0a: wake-up capability enabled by ACPI Jun 1 10:42:21 igor-laptop kernel: [ 2225.251115] i8042 aux 00:09: wake-up capability disabled by ACPI Jun 1 10:42:21 igor-laptop kernel: [ 2225.251133] i8042 kbd 00:08: wake-up capability enabled by ACPI Jun 1 10:42:21 igor-laptop kernel: [ 2225.251286] jmb38x_ms 0000:06:00.3: PCI INT A disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.252491] sdhci-pci 0000:06:00.1: PCI INT A disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.264130] uhci_hcd 0000:00:1d.2: PCI INT D disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.264142] uhci_hcd 0000:00:1d.1: PCI INT B disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.264325] uhci_hcd 0000:00:1a.1: PCI INT B disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.288059] uhci_hcd 0000:00:1a.0: PCI INT A disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.288097] uhci_hcd 0000:00:1d.3: PCI INT C disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.288135] uhci_hcd 0000:00:1d.0: PCI INT A disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.316051] ehci_hcd 0000:00:1d.7: PCI INT A disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.316068] ehci_hcd 0000:00:1a.7: PCI INT D disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.522872] PM: suspend of drv:sd dev:0:0:0:0 complete after 349.979 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.522901] PM: suspend of drv:scsi dev:target0:0:0 complete after 349.955 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.522927] PM: suspend of drv:scsi dev:host0 complete after 272.260 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.522969] ahci 0000:00:1f.2: BIOS update required for suspend/resume Jun 1 10:42:21 igor-laptop kernel: [ 2225.522976] pci_legacy_suspend(): ahci_pci_device_suspend+0x0/0x80 returns -5 Jun 1 10:42:21 igor-laptop kernel: [ 2225.522981] pm_op(): pci_pm_suspend+0x0/0x110 returns -5 Jun 1 10:42:21 igor-laptop kernel: [ 2225.522984] PM: suspend of drv:ahci dev:0000:00:1f.2 complete after 258.932 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.522987] PM: Device 0000:00:1f.2 failed to suspend async: error -5 Jun 1 10:42:21 igor-laptop kernel: [ 2225.576228] snd_hda_intel 0000:00:1b.0: PCI INT A disabled Jun 1 10:42:21 igor-laptop kernel: [ 2225.576270] ACPI handle has no context! Jun 1 10:42:21 igor-laptop kernel: [ 2225.592136] PM: suspend of drv:snd_hda_intel dev:0000:00:1b.0 complete after 327.889 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.592206] PM: Some devices failed to suspend Jun 1 10:42:21 igor-laptop kernel: [ 2225.592291] uhci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592298] uhci_hcd 0000:00:1a.0: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592325] usb usb3: root hub lost power or was reset Jun 1 10:42:21 igor-laptop kernel: [ 2225.592339] uhci_hcd 0000:00:1a.1: PCI INT B -> GSI 21 (level, low) -> IRQ 21 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592345] uhci_hcd 0000:00:1a.1: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592371] usb usb4: root hub lost power or was reset Jun 1 10:42:21 igor-laptop kernel: [ 2225.592387] ehci_hcd 0000:00:1a.7: PCI INT D -> GSI 19 (level, low) -> IRQ 19 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592395] ehci_hcd 0000:00:1a.7: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592843] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592851] uhci_hcd 0000:00:1d.0: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592854] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592863] uhci_hcd 0000:00:1d.1: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592878] usb usb5: root hub lost power or was reset Jun 1 10:42:21 igor-laptop kernel: [ 2225.592892] usb usb6: root hub lost power or was reset Jun 1 10:42:21 igor-laptop kernel: [ 2225.592895] uhci_hcd 0000:00:1d.2: PCI INT D -> GSI 16 (level, low) -> IRQ 16 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592903] uhci_hcd 0000:00:1d.2: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592906] uhci_hcd 0000:00:1d.3: PCI INT C -> GSI 18 (level, low) -> IRQ 18 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592915] uhci_hcd 0000:00:1d.3: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592930] usb usb7: root hub lost power or was reset Jun 1 10:42:21 igor-laptop kernel: [ 2225.592946] usb usb8: root hub lost power or was reset Jun 1 10:42:21 igor-laptop kernel: [ 2225.592949] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 20 (level, low) -> IRQ 20 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592957] ehci_hcd 0000:00:1d.7: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.592963] pci 0000:00:1e.0: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.597106] sd 0:0:0:0: [sda] Starting disk Jun 1 10:42:21 igor-laptop kernel: [ 2225.608138] snd_hda_intel 0000:00:1b.0: BAR 0: set to [mem 0xdf300000-0xdf303fff 64bit] (PCI address [0xdf300000-0xdf303fff]) Jun 1 10:42:21 igor-laptop kernel: [ 2225.608180] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0xf (was 0x100, writing 0x10b) Jun 1 10:42:21 igor-laptop kernel: [ 2225.608233] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0x3 (was 0x0, writing 0x10) Jun 1 10:42:21 igor-laptop kernel: [ 2225.608248] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100002) Jun 1 10:42:21 igor-laptop kernel: [ 2225.608299] snd_hda_intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22 Jun 1 10:42:21 igor-laptop kernel: [ 2225.608313] snd_hda_intel 0000:00:1b.0: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.608420] snd_hda_intel 0000:00:1b.0: irq 50 for MSI/MSI-X Jun 1 10:42:21 igor-laptop kernel: [ 2225.612095] firewire_ohci 0000:06:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100006) Jun 1 10:42:21 igor-laptop kernel: [ 2225.612181] sdhci-pci 0000:06:00.1: restoring config space at offset 0x1 (was 0x100003, writing 0x100007) Jun 1 10:42:21 igor-laptop kernel: [ 2225.612211] sdhci-pci 0000:06:00.1: PCI INT A -> GSI 16 (level, low) -> IRQ 16 Jun 1 10:42:21 igor-laptop kernel: [ 2225.612225] sdhci-pci 0000:06:00.1: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.612296] jmb38x_ms 0000:06:00.3: restoring config space at offset 0x1 (was 0x100003, writing 0x100007) Jun 1 10:42:21 igor-laptop kernel: [ 2225.612326] jmb38x_ms 0000:06:00.3: PCI INT A -> GSI 16 (level, low) -> IRQ 16 Jun 1 10:42:21 igor-laptop kernel: [ 2225.612332] jmb38x_ms 0000:06:00.3: setting latency timer to 64 Jun 1 10:42:21 igor-laptop kernel: [ 2225.699170] PM: resume of drv:uvcvideo dev:2-4:1.0 complete after 101.965 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.699179] PM: resume of drv:uvcvideo dev:2-4:1.1 complete after 101.932 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.699186] PM: resume of drv: dev:ep_00 complete after 101.917 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.699197] PM: resume of drv: dev:ep_83 complete after 101.972 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.716148] PM: resume of drv:hub dev:3-0:1.0 complete after 119.543 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.716155] PM: resume of drv: dev:ep_00 complete after 119.544 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.716161] PM: resume of drv:hub dev:5-0:1.0 complete after 119.420 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.716168] PM: resume of drv: dev:ep_00 complete after 119.381 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.716174] PM: resume of drv:hub dev:8-0:1.0 complete after 119.141 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.716181] PM: resume of drv: dev:ep_00 complete after 119.104 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.716186] PM: resume of drv: dev:ep_81 complete after 119.579 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.716191] PM: resume of drv: dev:ep_81 complete after 119.427 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.716197] PM: resume of drv: dev:ep_81 complete after 119.143 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.747148] firewire_core: skipped bus generations, destroying all nodes Jun 1 10:42:21 igor-laptop kernel: [ 2225.776093] PM: resume of drv:hp_accel dev:HPQ0004:00 complete after 167.225 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.777243] i8042 kbd 00:08: wake-up capability disabled by ACPI Jun 1 10:42:21 igor-laptop kernel: [ 2225.777278] ene_ir 00:0a: wake-up capability disabled by ACPI Jun 1 10:42:21 igor-laptop kernel: [ 2225.820100] PM: resume of drv:hub dev:4-0:1.0 complete after 223.436 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.820115] PM: resume of drv: dev:ep_00 complete after 223.444 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.820123] PM: resume of drv: dev:ep_81 complete after 223.456 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.820206] PM: resume of drv:hub dev:7-0:1.0 complete after 223.266 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.820221] PM: resume of drv: dev:ep_81 complete after 223.260 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.820238] PM: resume of drv: dev:ep_00 complete after 223.255 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.820295] PM: resume of drv:hub dev:6-0:1.0 complete after 223.453 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.820302] PM: resume of drv: dev:ep_00 complete after 223.415 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.820321] PM: resume of drv: dev:ep_81 complete after 223.457 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2225.932108] usb 4-2: reset full-speed USB device number 2 using uhci_hcd Jun 1 10:42:21 igor-laptop kernel: [ 2226.086714] PM: resume of drv:usbhid dev:4-2:1.0 complete after 489.393 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.086728] PM: resume of drv: dev:ep_81 complete after 489.384 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.086745] PM: resume of drv: dev:ep_00 complete after 489.329 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.086753] PM: resume of drv:usbhid dev:4-2:1.1 complete after 489.384 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.086764] PM: resume of drv: dev:ep_82 complete after 489.373 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.180555] usb 7-2: reset full-speed USB device number 2 using uhci_hcd Jun 1 10:42:21 igor-laptop kernel: [ 2226.244858] firewire_core: rediscovered device fw0 Jun 1 10:42:21 igor-laptop kernel: [ 2226.335066] btusb 7-2:1.0: no reset_resume for driver btusb? Jun 1 10:42:21 igor-laptop kernel: [ 2226.335068] btusb 7-2:1.1: no reset_resume for driver btusb? Jun 1 10:42:21 igor-laptop kernel: [ 2226.432082] usb 6-1: reset full-speed USB device number 2 using uhci_hcd Jun 1 10:42:21 igor-laptop kernel: [ 2226.578280] PM: resume of drv:nvidia dev:0000:01:00.0 complete after 985.301 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584296] PM: resume of drv:usb dev:7-2:1.0 complete after 986.693 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584308] PM: resume of drv: dev:ep_00 complete after 986.452 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584311] PM: resume of drv:usb dev:7-2:1.1 complete after 986.616 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584315] PM: resume of drv:usb dev:7-2:1.3 complete after 986.483 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584320] PM: resume of drv:usb dev:7-2:1.2 complete after 986.556 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584328] PM: resume of drv: dev:ep_03 complete after 986.588 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584331] PM: resume of drv: dev:ep_81 complete after 986.704 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584334] PM: resume of drv: dev:ep_83 complete after 986.617 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584337] PM: resume of drv: dev:ep_82 complete after 986.688 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584340] PM: resume of drv: dev:ep_02 complete after 986.667 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584344] PM: resume of drv: dev:ep_84 complete after 986.558 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.584352] PM: resume of drv: dev:ep_04 complete after 986.542 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.590883] PM: resume of drv: dev:ep_00 complete after 993.327 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.590887] PM: resume of drv:usb dev:6-1:1.0 complete after 993.424 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.590927] PM: resume of drv: dev:ep_82 complete after 993.395 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.590934] PM: resume of drv: dev:ep_81 complete after 993.426 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.590940] PM: resume of drv: dev:ep_01 complete after 993.456 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.592450] PM: resume of drv:sd dev:0:0:0:0 complete after 995.343 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.592461] PM: resume of drv:scsi_disk dev:0:0:0:0 complete after 802.688 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.592472] PM: resume of drv:scsi_device dev:0:0:0:0 complete after 995.324 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.600339] PM: resume of devices complete after 1008.129 msecs Jun 1 10:42:21 igor-laptop kernel: [ 2226.601293] PM: resume devices took 1.008 seconds Jun 1 10:42:21 igor-laptop kernel: [ 2226.601330] PM: Finishing wakeup. Jun 1 10:42:21 igor-laptop kernel: [ 2226.601332] Restarting tasks ... done. Jun 1 10:42:21 igor-laptop kernel: [ 2226.625660] video LNXVIDEO:01: Restoring backlight state Jun 1 10:42:22 igor-laptop kernel: [ 2227.478921] iwlwifi 0000:02:00.0: L1 Disabled; Enabling L0S Jun 1 10:42:22 igor-laptop kernel: [ 2227.481981] iwlwifi 0000:02:00.0: Radio type=0x1-0x2-0x0 Jun 1 10:42:22 igor-laptop kernel: [ 2227.527727] ADDRCONF(NETDEV_UP): wlan0: link is not ready Jun 1 10:42:22 igor-laptop kernel: [ 2227.532468] r8169 0000:03:00.0: eth0: link down Jun 1 10:42:22 igor-laptop kernel: [ 2227.533967] ADDRCONF(NETDEV_UP): eth0: link is not ready pm_suspend.log: Fri Jun 1 10:42:14 MSK 2012: Running hooks for suspend. Running hook /usr/lib/pm-utils/sleep.d/000kernel-change suspend suspend: /usr/lib/pm-utils/sleep.d/000kernel-change suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/00logging suspend suspend: Linux igor-laptop 3.2.0-25-generic #40-Ubuntu SMP Wed May 23 20:33:05 UTC 2012 i686 i686 i386 GNU/Linux Module Size Used by pci_stub 12550 1 vboxpci 22882 0 vboxnetadp 13328 0 vboxnetflt 27211 0 vboxdrv 252189 3 vboxpci,vboxnetadp,vboxnetflt dm_crypt 22528 0 snd_hda_codec_hdmi 31775 1 snd_hda_codec_idt 60251 1 arc4 12473 2 hp_wmi 13652 0 sparse_keymap 13658 1 hp_wmi rfcomm 38139 12 snd_hda_intel 32765 5 snd_hda_codec 109562 3 snd_hda_codec_hdmi,snd_hda_codec_idt,snd_hda_intel snd_hwdep 13276 1 snd_hda_codec bnep 17830 2 btusb 17912 2 bluetooth 158438 23 rfcomm,bnep,btusb joydev 17393 0 parport_pc 32114 0 snd_pcm 80845 4 snd_hda_codec_hdmi,snd_hda_intel,snd_hda_codec ppdev 12849 0 uvcvideo 67203 0 binfmt_misc 17292 1 videodev 86588 1 uvcvideo snd_seq_midi 13132 0 snd_rawmidi 25424 1 snd_seq_midi nvidia 10958194 43 snd_seq_midi_event 14475 1 snd_seq_midi snd_seq 51567 2 snd_seq_midi,snd_seq_midi_event ir_lirc_codec 12739 0 lirc_dev 18700 1 ir_lirc_codec snd_timer 28931 2 snd_pcm,snd_seq snd_seq_device 14172 3 snd_seq_midi,snd_rawmidi,snd_seq ir_mce_kbd_decoder 12681 0 ir_sony_decoder 12462 0 ir_jvc_decoder 12459 0 ir_rc6_decoder 12459 0 psmouse 87213 0 ir_rc5_decoder 12459 0 serio_raw 13027 0 iwlwifi 287934 0 rc_rc6_mce 12454 0 ir_nec_decoder 12459 0 ene_ir 18019 0 rc_core 21263 10 ir_lirc_codec,ir_mce_kbd_decoder,ir_sony_decoder,ir_jvc_decoder,ir_rc6_decoder,ir_rc5_decoder,rc_rc6_mce,ir_nec_decoder,ene_ir mac80211 436455 1 iwlwifi snd 62064 19 snd_hda_codec_hdmi,snd_hda_codec_idt,snd_hda_intel,snd_hda_codec,snd_hwdep,snd_pcm,snd_rawmidi,snd_seq,snd_timer,snd_seq_device cfg80211 178679 2 iwlwifi,mac80211 hp_accel 25728 0 lis3lv02d 19268 1 hp_accel input_polldev 13648 1 lis3lv02d mac_hid 13077 0 wmi 18744 1 hp_wmi jmb38x_ms 17406 0 soundcore 14635 1 snd snd_page_alloc 14115 2 snd_hda_intel,snd_pcm memstick 15857 1 jmb38x_ms firewire_sbp2 18346 0 lp 17455 0 parport 40930 3 parport_pc,ppdev,lp vesafb 13516 1 usbhid 41906 0 hid 77367 1 usbhid firewire_ohci 40180 0 firewire_core 56906 2 firewire_sbp2,firewire_ohci crc_itu_t 12627 1 firewire_core sdhci_pci 18324 0 sdhci 28241 1 sdhci_pci r8169 56321 0 video 19068 0 total used free shared buffers cached Mem: 3095544 2364260 731284 0 159020 1280240 -/+ buffers/cache: 925000 2170544 Swap: 1718916 0 1718916 /usr/lib/pm-utils/sleep.d/00logging suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/00powersave suspend suspend: /usr/lib/pm-utils/sleep.d/00powersave suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/01PulseAudio suspend suspend: Welcome to PulseAudio! Use "help" for usage information. >>> >>> Welcome to PulseAudio! Use "help" for usage information. >>> >>> Welcome to PulseAudio! Use "help" for usage information. >>> >>> /usr/lib/pm-utils/sleep.d/01PulseAudio suspend suspend: success. Running hook /etc/pm/sleep.d/10_grub-common suspend suspend: /etc/pm/sleep.d/10_grub-common suspend suspend: success. Running hook /etc/pm/sleep.d/10_unattended-upgrades-hibernate suspend suspend: /etc/pm/sleep.d/10_unattended-upgrades-hibernate suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/55NetworkManager suspend suspend: Having NetworkManager put all interaces to sleep...Failed. /usr/lib/pm-utils/sleep.d/55NetworkManager suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/60_wpa_supplicant suspend suspend: Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory /usr/lib/pm-utils/sleep.d/60_wpa_supplicant suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/75modules suspend suspend: /usr/lib/pm-utils/sleep.d/75modules suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/90clock suspend suspend: /usr/lib/pm-utils/sleep.d/90clock suspend suspend: not applicable. Running hook /usr/lib/pm-utils/sleep.d/94cpufreq suspend suspend: /usr/lib/pm-utils/sleep.d/94cpufreq suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/95anacron suspend suspend: stop: Unknown instance: /usr/lib/pm-utils/sleep.d/95anacron suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/95hdparm-apm suspend suspend: /usr/lib/pm-utils/sleep.d/95hdparm-apm suspend suspend: not applicable. Running hook /usr/lib/pm-utils/sleep.d/95led suspend suspend: /usr/lib/pm-utils/sleep.d/95led suspend suspend: not applicable. Running hook /usr/lib/pm-utils/sleep.d/98video-quirk-db-handler suspend suspend: nVidia binary video drive detected, not using quirks. /usr/lib/pm-utils/sleep.d/98video-quirk-db-handler suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/99video suspend suspend: kernel.acpi_video_flags = 0 /usr/lib/pm-utils/sleep.d/99video suspend suspend: success. Running hook /etc/pm/sleep.d/novatel_3g_suspend suspend suspend: /etc/pm/sleep.d/novatel_3g_suspend suspend suspend: success. Fri Jun 1 10:42:19 MSK 2012: performing suspend Fri Jun 1 10:42:21 MSK 2012: Awake. Fri Jun 1 10:42:21 MSK 2012: Running hooks for resume Running hook /etc/pm/sleep.d/novatel_3g_suspend resume suspend: /etc/pm/sleep.d/novatel_3g_suspend resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/99video resume suspend: /usr/lib/pm-utils/sleep.d/99video resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/98video-quirk-db-handler resume suspend: /usr/lib/pm-utils/sleep.d/98video-quirk-db-handler resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/95led resume suspend: /usr/lib/pm-utils/sleep.d/95led resume suspend: not applicable. Running hook /usr/lib/pm-utils/sleep.d/95hdparm-apm resume suspend: /dev/sda: setting Advanced Power Management level to 0xfe (254) APM_level = 254 /dev/sda: setting Advanced Power Management level to 0xfe (254) APM_level = 254 /usr/lib/pm-utils/sleep.d/95hdparm-apm resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/95anacron resume suspend: /usr/lib/pm-utils/sleep.d/95anacron resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/94cpufreq resume suspend: /usr/lib/pm-utils/sleep.d/94cpufreq resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/90clock resume suspend: /usr/lib/pm-utils/sleep.d/90clock resume suspend: not applicable. Running hook /usr/lib/pm-utils/sleep.d/75modules resume suspend: Reloaded unloaded modules. /usr/lib/pm-utils/sleep.d/75modules resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/60_wpa_supplicant resume suspend: Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory /usr/lib/pm-utils/sleep.d/60_wpa_supplicant resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/55NetworkManager resume suspend: Having NetworkManager wake interfaces back up...Failed. /usr/lib/pm-utils/sleep.d/55NetworkManager resume suspend: success. Running hook /etc/pm/sleep.d/10_unattended-upgrades-hibernate resume suspend: /etc/pm/sleep.d/10_unattended-upgrades-hibernate resume suspend: success. Running hook /etc/pm/sleep.d/10_grub-common resume suspend: /etc/pm/sleep.d/10_grub-common resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/01PulseAudio resume suspend: Welcome to PulseAudio! Use "help" for usage information. >>> >>> Welcome to PulseAudio! Use "help" for usage information. >>> >>> Welcome to PulseAudio! Use "help" for usage information. >>> >>> /usr/lib/pm-utils/sleep.d/01PulseAudio resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/00powersave resume suspend: /usr/lib/pm-utils/sleep.d/00powersave resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/00logging resume suspend: /usr/lib/pm-utils/sleep.d/00logging resume suspend: success. Running hook /usr/lib/pm-utils/sleep.d/000kernel-change resume suspend: /usr/lib/pm-utils/sleep.d/000kernel-change resume suspend: success. Fri Jun 1 10:42:22 MSK 2012: Finished.

  Read the article

• How to diagnose frequent segfaults

  - by Andreas Gohr

  My server is logging frequent segmentation faults to /var/log/kern.log in different tools. So far I've seen them in Perl, PHP and rsync. All installed software is up-to-date Debian packages. Here's an exerpt from the log file: Mar 2 01:07:54 gaz kernel: [ 5316.246303] imapsync[4533]: segfault at 8b ip 00007fb448c98fe6 sp 00007ffff571dd68 error 4 in libperl.so.5.10.1[7fb448bd7000+164000] Mar 2 01:17:42 gaz kernel: [ 5904.354307] php5-cgi[4441]: segfault at 2bb3dc8 ip 0000000002bb3dc8 sp 00007fffbeeaae48 error 15 Mar 2 02:54:05 gaz kernel: [11687.922316] php5-cgi[4495]: segfault at 2d7acf9 ip 0000000002d7acf9 sp 00007fff60c6eb18 error 15 Mar 2 10:50:08 gaz kernel: [40250.390322] BUG: unable to handle kernel paging request at 00000000024b03f0 Mar 2 10:50:08 gaz kernel: [40250.390341] IP: [<00000000024b03f0>] 0x24b03f0 Mar 2 10:50:08 gaz kernel: [40250.390353] PGD 208c71067 PUD 21c811067 PMD 209329067 PTE 8000000211c88067 Mar 2 10:50:08 gaz kernel: [40250.390365] Oops: 0011 [#1] SMP Mar 2 10:50:08 gaz kernel: [40250.390373] last sysfs file: /sys/devices/pci0000:00/0000:00:12.0/host4/target4:0:0/4:0:0:0/block/sdb/stat Mar 2 10:50:08 gaz kernel: [40250.390386] CPU 1 Mar 2 10:50:08 gaz kernel: [40250.390392] Modules linked in: cpufreq_userspace cpufreq_stats cpufreq_powersave cpufreq_conservative xt_recent xt_tcpudp iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ ipv4 ip6table_filter ip6_tables xt_DSCP xt_TCPMSS ipt_LOG ipt_REJECT iptable_mangle iptable_filter xt_multiport xt_state xt_limit xt_conntrack nf_conntrack_ftp nf_conntrack ip_tables x_tables loop snd _hda_codec_atihdmi snd_hda_intel snd_hda_codec snd_hwdep snd_pcm radeon snd_timer ttm snd drm_kms_helper soundcore drm snd_page_alloc i2c_algo_bit shpchp i2c_piix4 edac_core pcspkr k8temp evdev edac_m ce_amd pci_hotplug i2c_core button ext3 jbd mbcache dm_mod powernow_k8 aacraid 3w_9xxx 3w_xxxx raid10 raid456 async_raid6_recov async_pq raid6_pq async_xor xor async_memcpy async_tx raid1 raid0 md_mod sata_nv sata_sil sata_via sd_mod crc_t10dif ata_generic ahci pata_atiixp ohci_hcd libata r8169 mii thermal ehci_hcd processor thermal_sys scsi_mod usbcore nls_base [last unloaded: scsi_wait_scan] Mar 2 10:50:08 gaz kernel: [40250.390566] Pid: 11482, comm: munin-limits Not tainted 2.6.32-5-amd64 #1 MS-7368 Mar 2 10:50:08 gaz kernel: [40250.390576] RIP: 0010:[<00000000024b03f0>] [<00000000024b03f0>] 0x24b03f0 Mar 2 10:50:08 gaz kernel: [40250.390586] RSP: 0018:ffff88021cc8dec0 EFLAGS: 00010286 Mar 2 10:50:08 gaz kernel: [40250.390593] RAX: 000000001ddc1000 RBX: 0000000000000010 RCX: ffffffff810f9904 Mar 2 10:50:08 gaz kernel: [40250.390600] RDX: 0000000000000000 RSI: ffffea0007688200 RDI: 0000000000000286 Mar 2 10:50:08 gaz kernel: [40250.390608] RBP: 00000000ffffffea R08: 0000000000000025 R09: 7865542f30312e35 Mar 2 10:50:08 gaz kernel: [40250.390615] R10: 000000d01cc8ddf8 R11: 0000000000000246 R12: ffff88021cc8def8 Mar 2 10:50:08 gaz kernel: [40250.390622] R13: 0000000002295010 R14: 00000000022c9db0 R15: 0000000002488d78 Mar 2 10:50:08 gaz kernel: [40250.390630] FS: 00007f3b3c8b2700(0000) GS:ffff880008d00000(0000) knlGS:0000000000000000 Mar 2 10:50:08 gaz kernel: [40250.390641] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Mar 2 10:50:08 gaz kernel: [40250.390648] CR2: 00000000024b03f0 CR3: 000000021c5d1000 CR4: 00000000000006e0 Mar 2 10:50:08 gaz kernel: [40250.390656] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Mar 2 10:50:08 gaz kernel: [40250.390663] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Mar 2 10:50:08 gaz kernel: [40250.390671] Process munin-limits (pid: 11482, threadinfo ffff88021cc8c000, task ffff88021bf59530) Mar 2 10:50:08 gaz kernel: [40250.390681] Stack: Mar 2 10:50:08 gaz kernel: [40250.390687] ffffffff810f1d4a ffff880208c63228 0000000000000000 00007fffc2dcecc0 Mar 2 10:50:08 gaz kernel: [40250.390697] <0> 00000000024ba2b0 0000000002295010 ffffffff810f1e3d 0000000000000004 Mar 2 10:50:08 gaz kernel: [40250.390712] <0> ffff88021bf59530 ffff88021c4edc00 ffffffff812fe0b6 ffff88021c4edc60 Mar 2 10:50:08 gaz kernel: [40250.390732] Call Trace: Mar 2 10:50:08 gaz kernel: [40250.390742] [<ffffffff810f1d4a>] ? vfs_fstatat+0x2c/0x57 Mar 2 10:50:08 gaz kernel: [40250.390750] [<ffffffff810f1e3d>] ? sys_newstat+0x11/0x30 Mar 2 10:50:08 gaz kernel: [40250.390760] [<ffffffff812fe0b6>] ? do_page_fault+0x2e0/0x2fc Mar 2 10:50:08 gaz kernel: [40250.390768] [<ffffffff812fbf55>] ? page_fault+0x25/0x30 Mar 2 10:50:08 gaz kernel: [40250.390777] [<ffffffff81010b42>] ? system_call_fastpath+0x16/0x1b Mar 2 10:50:08 gaz kernel: [40250.390783] Code: Bad RIP value. Mar 2 10:50:08 gaz kernel: [40250.390791] RIP [<00000000024b03f0>] 0x24b03f0 Mar 2 10:50:08 gaz kernel: [40250.390799] RSP <ffff88021cc8dec0> Mar 2 10:50:08 gaz kernel: [40250.390805] CR2: 00000000024b03f0 Mar 2 10:50:08 gaz kernel: [40250.391051] ---[ end trace 1cc1473b539c7f6e ]--- Mar 2 11:42:20 gaz kernel: [43382.242301] php5-cgi[10963]: segfault at d81160 ip 0000000000d81160 sp 00007fff3adcb058 error 15 Mar 2 21:51:14 gaz kernel: [79916.418302] php5-cgi[20089]: segfault at 1c59dc8 ip 0000000001c59dc8 sp 00007fff9b877fb8 error 15 Mar 3 03:45:01 gaz kernel: [101143.334305] munin-update[22519] general protection ip:7f516dce204c sp:7fff6049a978 error:0 in libperl.so.5.10.1[7f516dc7d000+164000] Mar 3 11:22:37 gaz kernel: [128599.570307] php5-cgi[22888]: segfault at 36485a8 ip 00000000036485a8 sp 00007fff2d56e1c8 error 15 Mar 4 08:32:17 gaz kernel: [204779.842304] php5-cgi[22090]: segfault at 18 ip 0000000000689e5e sp 00007fff677a6a48 error 6 in php5-cgi[400000+6f9000] Mar 4 10:01:02 gaz kernel: [210104.434706] rsync[22236] general protection ip:7f14a07137f9 sp:7fff88f940b8 error:0 in libc-2.11.2.so[7f14a069d000+158000] Mar 4 11:32:22 gaz kernel: [215584.262316] BUG: unable to handle kernel paging request at 00000000ffffff9c Mar 4 11:32:22 gaz kernel: [215584.262331] IP: [<00000000ffffff9c>] 0xffffff9c Mar 4 11:32:22 gaz kernel: [215584.262343] PGD 0 Mar 4 11:32:22 gaz kernel: [215584.262350] Oops: 0010 [#2] SMP Mar 4 11:32:22 gaz kernel: [215584.262359] last sysfs file: /sys/devices/pci0000:00/0000:00:12.0/host4/target4:0:0/4:0:0:0/block/sdb/stat Mar 4 11:32:22 gaz kernel: [215584.262371] CPU 1 Mar 4 11:32:22 gaz kernel: [215584.262378] Modules linked in: cpufreq_userspace cpufreq_stats cpufreq_powersave cpufreq_conservative xt_recent xt_tcpudp iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 ip6table_filter ip6_tables xt_DSCP xt_TCPMSS ipt_LOG ipt_REJECT iptable_mangle iptable_filter xt_multiport xt_state xt_limit xt_conntrack nf_conntrack_ftp nf_conntrack ip_tables x_tables loop snd_hda_codec_atihdmi snd_hda_intel snd_hda_codec snd_hwdep snd_pcm radeon snd_timer ttm snd drm_kms_helper soundcore drm snd_page_alloc i2c_algo_bit shpchp i2c_piix4 edac_core pcspkr k8temp evdev edac_mce_amd pci_hotplug i2c_core button ext3 jbd mbcache dm_mod powernow_k8 aacraid 3w_9xxx 3w_xxxx raid10 raid456 async_raid6_recov async_pq raid6_pq async_xor xor async_memcpy async_tx raid1 raid0 md_mod sata_nv sata_sil sata_via sd_mod crc_t10dif ata_generic ahci pata_atiixp ohci_hcd libata r8169 mii thermal ehci_hcd processor thermal_sys scsi_mod usbcore nls_base [last unloaded: scsi_wait_scan] Mar 4 11:32:22 gaz kernel: [215584.262552] Pid: 1960, comm: proxymap Tainted: G D 2.6.32-5-amd64 #1 MS-7368 Mar 4 11:32:22 gaz kernel: [215584.262563] RIP: 0010:[<00000000ffffff9c>] [<00000000ffffff9c>] 0xffffff9c Mar 4 11:32:22 gaz kernel: [215584.262573] RSP: 0018:ffff880209257e00 EFLAGS: 00010212 Mar 4 11:32:22 gaz kernel: [215584.262580] RAX: ffff8801514eb780 RBX: ffffffff810efb2d RCX: 0000000000000000 Mar 4 11:32:22 gaz kernel: [215584.262590] RDX: 0000000000000020 RSI: 0000000000000001 RDI: ffff8801514eb780 Mar 4 11:32:22 gaz kernel: [215584.262600] RBP: 00000000ffffffe9 R08: 0000000000000000 R09: 0000000000000000 Mar 4 11:32:22 gaz kernel: [215584.262611] R10: ffff880209257e78 R11: ffffffff81152c7c R12: 0000000000000001 Mar 4 11:32:22 gaz kernel: [215584.262622] R13: 0000000000008001 R14: 0000000000000024 R15: 00000000ffffff9c Mar 4 11:32:22 gaz kernel: [215584.262633] FS: 00007fca4de35700(0000) GS:ffff880008d00000(0000) knlGS:0000000000000000 Mar 4 11:32:22 gaz kernel: [215584.262644] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Mar 4 11:32:22 gaz kernel: [215584.262650] CR2: 00000000ffffff9c CR3: 00000001c9cbb000 CR4: 00000000000006e0 Mar 4 11:32:22 gaz kernel: [215584.262661] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Mar 4 11:32:22 gaz kernel: [215584.262671] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Mar 4 11:32:22 gaz kernel: [215584.262682] Process proxymap (pid: 1960, threadinfo ffff880209256000, task ffff88021c4b1c40) Mar 4 11:32:22 gaz kernel: [215584.262693] Stack: Mar 4 11:32:22 gaz kernel: [215584.262698] ffffffff810f8566 ffff880209257e78 ffff88021c7bf000 ffff88021c7bf0c8 Mar 4 11:32:22 gaz kernel: [215584.262709] <0> 0000800000000000 ffff88021fc0f000 ffff880209257e78 00000000fffffffe Mar 4 11:32:22 gaz kernel: [215584.262724] <0> ffffffff810e5881 ffff880209257f48 0000000000000286 ffff88021fc0f000 Mar 4 11:32:22 gaz kernel: [215584.262743] Call Trace: Mar 4 11:32:22 gaz kernel: [215584.262753] [<ffffffff810f8566>] ? do_filp_open+0xa7/0x94b Mar 4 11:32:22 gaz kernel: [215584.262763] [<ffffffff810e5881>] ? virt_to_head_page+0x9/0x2a Mar 4 11:32:22 gaz kernel: [215584.262771] [<ffffffff810f9904>] ? user_path_at+0x52/0x79 Mar 4 11:32:22 gaz kernel: [215584.262779] [<ffffffff810cfec1>] ? get_unmapped_area+0xd7/0x139 Mar 4 11:32:22 gaz kernel: [215584.262787] [<ffffffff811019d5>] ? alloc_fd+0x67/0x10c Mar 4 11:32:22 gaz kernel: [215584.262795] [<ffffffff810eceaf>] ? do_sys_open+0x55/0xfc Mar 4 11:32:22 gaz kernel: [215584.262804] [<ffffffff81010b42>] ? system_call_fastpath+0x16/0x1b Mar 4 11:32:22 gaz kernel: [215584.262811] Code: Bad RIP value. Mar 4 11:32:22 gaz kernel: [215584.262819] RIP [<00000000ffffff9c>] 0xffffff9c Mar 4 11:32:22 gaz kernel: [215584.262828] RSP <ffff880209257e00> Mar 4 11:32:22 gaz kernel: [215584.262833] CR2: 00000000ffffff9c Mar 4 11:32:22 gaz kernel: [215584.263077] ---[ end trace 1cc1473b539c7f6f ]--- As you can see there are segfaults, a general protection fault and a Kernel Oops. My first guess was that there's a Hardware problem of some sort and I asked my Hoster (it's a rented root server) to do a full hardwarecheck - they did, but couldn't find any problem. I don't know what and how they checked but their support team is usually quite good. I ran memtester and cpuburn myself and couldn't find any error either. Unfortunately I have no reliable way to reproduce these segfaults, they seem to be more or less random. On a hunch I disabled the firewall of the system and ran one of the programs that segfaulted regularily (imapsync) and it seemed to take longer to segfault than before, so the problem might be related to the network stack. Or could just be a random thing. Here are the kernel specs: # uname -a Linux gaz 2.6.32-5-amd64 #1 SMP Wed Jan 12 03:40:32 UTC 2011 x86_64 GNU/Linux # cat /etc/debian_version 6.0 # lsmod Module Size Used by cpufreq_userspace 1992 0 cpufreq_stats 2659 0 cpufreq_powersave 902 0 cpufreq_conservative 5162 0 xt_recent 5977 0 xt_tcpudp 2319 0 iptable_nat 4299 0 nf_nat 13388 1 iptable_nat nf_conntrack_ipv4 9833 3 iptable_nat,nf_nat nf_defrag_ipv4 1139 1 nf_conntrack_ipv4 ip6table_filter 2384 0 ip6_tables 15075 1 ip6table_filter xt_DSCP 1995 0 xt_TCPMSS 2919 0 ipt_LOG 4518 0 ipt_REJECT 1953 0 iptable_mangle 2817 0 iptable_filter 2258 0 xt_multiport 2267 0 xt_state 1303 0 xt_limit 1782 0 xt_conntrack 2407 0 nf_conntrack_ftp 5537 0 nf_conntrack 46535 6 iptable_nat,nf_nat,nf_conntrack_ipv4,xt_state,xt_conntrack,nf_conntrack_ftp ip_tables 13899 3 iptable_nat,iptable_mangle,iptable_filter x_tables 12845 13 xt_recent,xt_tcpudp,iptable_nat,ip6_tables,xt_DSCP,xt_TCPMSS,ipt_LOG,ipt_REJECT,xt_multiport,xt_state,xt_limit,xt_conntrack,ip_tables loop 11799 0 radeon 573996 0 ttm 39986 1 radeon drm_kms_helper 20065 1 radeon snd_hda_codec_atihdmi 2251 1 drm 142359 3 radeon,ttm,drm_kms_helper snd_hda_intel 20019 0 i2c_algo_bit 4225 1 radeon pcspkr 1699 0 i2c_piix4 8328 0 snd_hda_codec 54244 2 snd_hda_codec_atihdmi,snd_hda_intel i2c_core 15712 5 radeon,drm_kms_helper,drm,i2c_algo_bit,i2c_piix4 snd_hwdep 5380 1 snd_hda_codec snd_pcm 60503 2 snd_hda_intel,snd_hda_codec snd_timer 15582 1 snd_pcm snd 46446 5 snd_hda_intel,snd_hda_codec,snd_hwdep,snd_pcm,snd_timer soundcore 4598 1 snd evdev 7352 3 snd_page_alloc 6249 2 snd_hda_intel,snd_pcm k8temp 3283 0 edac_core 29261 0 edac_mce_amd 6433 0 shpchp 26264 0 pci_hotplug 21203 1 shpchp button 4650 0 ext3 106518 2 jbd 37085 1 ext3 mbcache 5050 1 ext3 dm_mod 53754 0 powernow_k8 10978 1 aacraid 59779 0 3w_9xxx 28684 0 3w_xxxx 20569 0 raid10 17809 0 raid456 44500 0 async_raid6_recov 5170 1 raid456 async_pq 3479 2 raid456,async_raid6_recov raid6_pq 77179 2 async_raid6_recov,async_pq async_xor 2478 3 raid456,async_raid6_recov,async_pq xor 4380 1 async_xor async_memcpy 1198 2 raid456,async_raid6_recov async_tx 1734 5 raid456,async_raid6_recov,async_pq,async_xor,async_memcpy raid1 18431 3 raid0 5517 0 md_mod 73824 7 raid10,raid456,raid1,raid0 sata_nv 19166 0 sata_sil 7412 0 sata_via 7928 0 sd_mod 29889 8 crc_t10dif 1276 1 sd_mod ata_generic 3047 0 ahci 32374 6 r8169 29229 0 mii 3210 1 r8169 thermal 11674 0 pata_atiixp 3489 0 libata 133632 6 sata_nv,sata_sil,sata_via,ata_generic,ahci,pata_atiixp ohci_hcd 19212 0 ehci_hcd 31151 0 processor 29935 1 powernow_k8 thermal_sys 11942 2 thermal,processor scsi_mod 122149 5 aacraid,3w_9xxx,3w_xxxx,sd_mod,libata usbcore 122034 3 ohci_hcd,ehci_hcd nls_base 6377 1 usbcore # free total used free shared buffers cached Mem: 8166128 1228036 6938092 0 140412 782060 -/+ buffers/cache: 305564 7860564 Swap: 2102456 0 2102456 So, basically my questions are: How can I diagnose this further? Is there any data in the log above that could help me to isolate the troublemaker? Are there any known problems with the above hardware/software I overlooked when googling for it? Is there a way to prevent the kernel from autoloading modules (I probably don't need all these modules and one of them might be the culprit)

  Read the article

• Slow filesystem access

  - by danneh3826

  I'm trying to diagnose a slow filesystem issue on a server I look after. It's been ongoing for quite some time, and I've run out of ideas as to what I can try. Here's the thick of it. The server itself is a Dell Poweredge T310. It has 4 SAS hard drives in it, configured at RAID5, and is running Citrix XenServer 5.6. The VM is a (relatively) old Debian 5.0.6 installation. It's given 4 cores, and 4Gb's of RAM. It has 3 volumes. A 10Gb volume (ext3) for the system, 980Gb volume (xfs) for data (~94% full), and another 200Gb volume (xfs) for data (~13% full). Now here's the weird thing. Read/write access to the 980Gb volume is really slow. I might get 5Mb/s out of it if I'm lucky. At first I figured it was actually disk access in the system, or at a hypervisor level, but ruled that out entirely as other VMs on the same host are running perfectly fine (a good couple hundred Mb/s disk r/w access). So then I started to target this particular VM. I started thinking it was XFS, but to prove it I wasn't going to attempt to change the filesystem on the 980Gb drive, with years and years of billions of files on there. So I provisioned the 200Gb drive, and did the same read/write test (basically dd), and got a good couple hundred Mb/s r/w access to it. So that ruled out the VM, the hardware, and the filesystem type. There's also a lot of these in /var/log/kern.log; (sorry, this is quite long) Sep 4 10:16:59 uriel kernel: [32571790.564689] httpd: page allocation failure. order:5, mode:0x4020 Sep 4 10:16:59 uriel kernel: [32571790.564693] Pid: 7318, comm: httpd Not tainted 2.6.32-4-686-bigmem #1 Sep 4 10:16:59 uriel kernel: [32571790.564696] Call Trace: Sep 4 10:16:59 uriel kernel: [32571790.564705] [<c1092a4d>] ? __alloc_pages_nodemask+0x476/0x4e0 Sep 4 10:16:59 uriel kernel: [32571790.564711] [<c1092ac3>] ? __get_free_pages+0xc/0x17 Sep 4 10:16:59 uriel kernel: [32571790.564716] [<c10b632e>] ? __kmalloc+0x30/0x128 Sep 4 10:16:59 uriel kernel: [32571790.564722] [<c11dd774>] ? pskb_expand_head+0x4f/0x157 Sep 4 10:16:59 uriel kernel: [32571790.564727] [<c11ddbbf>] ? __pskb_pull_tail+0x41/0x1fb Sep 4 10:16:59 uriel kernel: [32571790.564732] [<c11e4882>] ? dev_queue_xmit+0xe4/0x38e Sep 4 10:16:59 uriel kernel: [32571790.564738] [<c1205902>] ? ip_finish_output+0x0/0x5c Sep 4 10:16:59 uriel kernel: [32571790.564742] [<c12058c7>] ? ip_finish_output2+0x187/0x1c2 Sep 4 10:16:59 uriel kernel: [32571790.564747] [<c1204dc8>] ? ip_local_out+0x15/0x17 Sep 4 10:16:59 uriel kernel: [32571790.564751] [<c12055a9>] ? ip_queue_xmit+0x31e/0x379 Sep 4 10:16:59 uriel kernel: [32571790.564758] [<c1279a90>] ? _spin_lock_bh+0x8/0x1e Sep 4 10:16:59 uriel kernel: [32571790.564767] [<eda15a8d>] ? __nf_ct_refresh_acct+0x66/0xa4 [nf_conntrack] Sep 4 10:16:59 uriel kernel: [32571790.564773] [<c103bf42>] ? _local_bh_enable_ip+0x16/0x6e Sep 4 10:16:59 uriel kernel: [32571790.564779] [<c1214593>] ? tcp_transmit_skb+0x595/0x5cc Sep 4 10:16:59 uriel kernel: [32571790.564785] [<c1005c4f>] ? xen_restore_fl_direct_end+0x0/0x1 Sep 4 10:16:59 uriel kernel: [32571790.564791] [<c12165ea>] ? tcp_write_xmit+0x7a3/0x874 Sep 4 10:16:59 uriel kernel: [32571790.564796] [<c121203a>] ? tcp_ack+0x1611/0x1802 Sep 4 10:16:59 uriel kernel: [32571790.564801] [<c10055ec>] ? xen_force_evtchn_callback+0xc/0x10 Sep 4 10:16:59 uriel kernel: [32571790.564806] [<c121392f>] ? tcp_established_options+0x1d/0x8b Sep 4 10:16:59 uriel kernel: [32571790.564811] [<c1213be4>] ? tcp_current_mss+0x38/0x53 Sep 4 10:16:59 uriel kernel: [32571790.564816] [<c1216701>] ? __tcp_push_pending_frames+0x1e/0x50 Sep 4 10:16:59 uriel kernel: [32571790.564821] [<c1212246>] ? tcp_data_snd_check+0x1b/0xd2 Sep 4 10:16:59 uriel kernel: [32571790.564825] [<c1212de3>] ? tcp_rcv_established+0x5d0/0x626 Sep 4 10:16:59 uriel kernel: [32571790.564831] [<c121902c>] ? tcp_v4_do_rcv+0x15f/0x2cf Sep 4 10:16:59 uriel kernel: [32571790.564835] [<c1219561>] ? tcp_v4_rcv+0x3c5/0x5c0 Sep 4 10:16:59 uriel kernel: [32571790.564841] [<c120197e>] ? ip_local_deliver_finish+0x10c/0x18c Sep 4 10:16:59 uriel kernel: [32571790.564846] [<c12015a4>] ? ip_rcv_finish+0x2c4/0x2d8 Sep 4 10:16:59 uriel kernel: [32571790.564852] [<c11e3b71>] ? netif_receive_skb+0x3bb/0x3d6 Sep 4 10:16:59 uriel kernel: [32571790.564864] [<ed823efc>] ? xennet_poll+0x9b8/0xafc [xen_netfront] Sep 4 10:16:59 uriel kernel: [32571790.564869] [<c11e40ee>] ? net_rx_action+0x96/0x194 Sep 4 10:16:59 uriel kernel: [32571790.564874] [<c103bd4c>] ? __do_softirq+0xaa/0x151 Sep 4 10:16:59 uriel kernel: [32571790.564878] [<c103be24>] ? do_softirq+0x31/0x3c Sep 4 10:16:59 uriel kernel: [32571790.564883] [<c103befa>] ? irq_exit+0x26/0x58 Sep 4 10:16:59 uriel kernel: [32571790.564890] [<c118ff9f>] ? xen_evtchn_do_upcall+0x12c/0x13e Sep 4 10:16:59 uriel kernel: [32571790.564896] [<c1008c3f>] ? xen_do_upcall+0x7/0xc Sep 4 10:16:59 uriel kernel: [32571790.564899] Mem-Info: Sep 4 10:16:59 uriel kernel: [32571790.564902] DMA per-cpu: Sep 4 10:16:59 uriel kernel: [32571790.564905] CPU 0: hi: 0, btch: 1 usd: 0 Sep 4 10:16:59 uriel kernel: [32571790.564908] CPU 1: hi: 0, btch: 1 usd: 0 Sep 4 10:16:59 uriel kernel: [32571790.564911] CPU 2: hi: 0, btch: 1 usd: 0 Sep 4 10:16:59 uriel kernel: [32571790.564914] CPU 3: hi: 0, btch: 1 usd: 0 Sep 4 10:16:59 uriel kernel: [32571790.564916] Normal per-cpu: Sep 4 10:16:59 uriel kernel: [32571790.564919] CPU 0: hi: 186, btch: 31 usd: 175 Sep 4 10:16:59 uriel kernel: [32571790.564922] CPU 1: hi: 186, btch: 31 usd: 165 Sep 4 10:16:59 uriel kernel: [32571790.564925] CPU 2: hi: 186, btch: 31 usd: 30 Sep 4 10:16:59 uriel kernel: [32571790.564928] CPU 3: hi: 186, btch: 31 usd: 140 Sep 4 10:16:59 uriel kernel: [32571790.564931] HighMem per-cpu: Sep 4 10:16:59 uriel kernel: [32571790.564933] CPU 0: hi: 186, btch: 31 usd: 159 Sep 4 10:16:59 uriel kernel: [32571790.564936] CPU 1: hi: 186, btch: 31 usd: 22 Sep 4 10:16:59 uriel kernel: [32571790.564939] CPU 2: hi: 186, btch: 31 usd: 24 Sep 4 10:16:59 uriel kernel: [32571790.564942] CPU 3: hi: 186, btch: 31 usd: 13 Sep 4 10:16:59 uriel kernel: [32571790.564947] active_anon:485974 inactive_anon:121138 isolated_anon:0 Sep 4 10:16:59 uriel kernel: [32571790.564948] active_file:75215 inactive_file:79510 isolated_file:0 Sep 4 10:16:59 uriel kernel: [32571790.564949] unevictable:0 dirty:516 writeback:15 unstable:0 Sep 4 10:16:59 uriel kernel: [32571790.564950] free:230770 slab_reclaimable:36661 slab_unreclaimable:21249 Sep 4 10:16:59 uriel kernel: [32571790.564952] mapped:20016 shmem:29450 pagetables:5600 bounce:0 Sep 4 10:16:59 uriel kernel: [32571790.564958] DMA free:2884kB min:72kB low:88kB high:108kB active_anon:0kB inactive_anon:0kB active_file:5692kB inactive_file:724kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15872kB mlocked:0kB dirty:8kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:5112kB slab_unreclaimable:156kB kernel_stack:56kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no Sep 4 10:16:59 uriel kernel: [32571790.564964] lowmem_reserve[]: 0 698 4143 4143 Sep 4 10:16:59 uriel kernel: [32571790.564977] Normal free:143468kB min:3344kB low:4180kB high:5016kB active_anon:56kB inactive_anon:2068kB active_file:131812kB inactive_file:131728kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:715256kB mlocked:0kB dirty:156kB writeback:0kB mapped:308kB shmem:4kB slab_reclaimable:141532kB slab_unreclaimable:84840kB kernel_stack:1928kB pagetables:22400kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no Sep 4 10:16:59 uriel kernel: [32571790.564983] lowmem_reserve[]: 0 0 27559 27559 Sep 4 10:16:59 uriel kernel: [32571790.564995] HighMem free:776728kB min:512kB low:4636kB high:8760kB active_anon:1943840kB inactive_anon:482484kB active_file:163356kB inactive_file:185588kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3527556kB mlocked:0kB dirty:1900kB writeback:60kB mapped:79756kB shmem:117796kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no Sep 4 10:16:59 uriel kernel: [32571790.565001] lowmem_reserve[]: 0 0 0 0 Sep 4 10:16:59 uriel kernel: [32571790.565011] DMA: 385*4kB 16*8kB 3*16kB 9*32kB 6*64kB 2*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2900kB Sep 4 10:16:59 uriel kernel: [32571790.565032] Normal: 21505*4kB 6508*8kB 273*16kB 24*32kB 3*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 143412kB Sep 4 10:16:59 uriel kernel: [32571790.565054] HighMem: 949*4kB 8859*8kB 7063*16kB 6186*32kB 4631*64kB 727*128kB 6*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 776604kB Sep 4 10:16:59 uriel kernel: [32571790.565076] 198980 total pagecache pages Sep 4 10:16:59 uriel kernel: [32571790.565079] 14850 pages in swap cache Sep 4 10:16:59 uriel kernel: [32571790.565082] Swap cache stats: add 2556273, delete 2541423, find 82961339/83153719 Sep 4 10:16:59 uriel kernel: [32571790.565085] Free swap = 250592kB Sep 4 10:16:59 uriel kernel: [32571790.565087] Total swap = 385520kB Sep 4 10:16:59 uriel kernel: [32571790.575454] 1073152 pages RAM Sep 4 10:16:59 uriel kernel: [32571790.575458] 888834 pages HighMem Sep 4 10:16:59 uriel kernel: [32571790.575461] 11344 pages reserved Sep 4 10:16:59 uriel kernel: [32571790.575463] 1090481 pages shared Sep 4 10:16:59 uriel kernel: [32571790.575465] 737188 pages non-shared Now, I've no idea what this means. There's plenty of free memory; total used free shared buffers cached Mem: 4247232 3455904 791328 0 5348 736412 -/+ buffers/cache: 2714144 1533088 Swap: 385520 131004 254516 Though now I see the swap is relatively low in size, but would that matter? I've been starting to think about fragmentation, or inode usage on that large partition, but a recent fsck on it showed is as only like 0.5% fragmented. Which leaves me with inode usage, but how much of an effect really would a large inode table or filesystem TOC have? I've love to hear people's opinions on this. It's driving me potty! df -h output; Filesystem Size Used Avail Use% Mounted on /dev/xvda1 9.5G 6.6G 2.4G 74% / tmpfs 2.1G 0 2.1G 0% /lib/init/rw udev 10M 520K 9.5M 6% /dev tmpfs 2.1G 0 2.1G 0% /dev/shm /dev/xvdb 980G 921G 59G 94% /data

  Read the article

• Did I lose my RAID again?

  - by BarsMonster

  Hi! A little history: 2 years ago I was really excited to find out that mdadm is so powerful that it even can reshape arrays, so you can start with a smaller array and then grow it as you need. I've bought 3x1Tb drives and made a RAID-5. It was fine for a year. Then I bought 2x more, and tried to reshape to RAID-6 out of 5 drives, and due to some mess with superblock versions, lost all content. Had to rebuild it from scratch, but 2Tb of data were gone. Yesterday I bought 2 more drives, and this time I had everything: properly built array, UPS. I've disabled write intent map, added 2 new drives as spares and run a command to grow array to 7-disks. It started working, but speed was ridiculously slow, ~100kb/sec. After processing first 37Mb at such an amazing speed, one of old HDDs fails. I properly shutdown the PC and disconnected the failed drive. After bootup it appeared that it recreated the intent map as it was still in mdadm config, so I removed it from config and rebooted again. Now all I see is that all mdadm processes deadlock, and don't do anything. PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1937 root 20 0 12992 608 444 D 0 0.1 0:00.00 mdadm 2283 root 20 0 12992 852 704 D 0 0.1 0:00.01 mdadm 2287 root 20 0 0 0 0 D 0 0.0 0:00.01 md0_reshape 2288 root 18 -2 12992 820 676 D 0 0.1 0:00.01 mdadm And all I see in mdstat is: $ cat /proc/mdstat Personalities : [linear] [multipath] [raid0] [raid1] [raid6] [raid5] [raid4] [raid10] md0 : active raid6 sdb1[1] sdg1[4] sdf1[7] sde1[6] sdd1[0] sdc1[5] 2929683456 blocks super 1.2 level 6, 1024k chunk, algorithm 2 [7/6] [UU_UUUU] [>....................] reshape = 0.0% (37888/976561152) finish=567604147.2min speed=0K/sec I've already tried mdadm 2.6.7, 3.1.4 and 3.2 - nothing helps. Did I lose my data again? Any suggestions on how can I make this work? OS is Ubuntu Server 10.04.2. PS. Needless to say, the data is inaccessible - I cannot mount /dev/md0 to save the most valuable data. You can see my disappointment - the very specific thing I was excited about failed twice taking 5Tb of my data with it. Update: It appears there is some nice info in kern.log: 21:38:48 ...: [ 166.522055] raid5: reshape will continue 21:38:48 ...: [ 166.522085] raid5: device sdb1 operational as raid disk 1 21:38:48 ...: [ 166.522091] raid5: device sdg1 operational as raid disk 4 21:38:48 ...: [ 166.522097] raid5: device sdf1 operational as raid disk 5 21:38:48 ...: [ 166.522102] raid5: device sde1 operational as raid disk 6 21:38:48 ...: [ 166.522107] raid5: device sdd1 operational as raid disk 0 21:38:48 ...: [ 166.522111] raid5: device sdc1 operational as raid disk 3 21:38:48 ...: [ 166.523942] raid5: allocated 7438kB for md0 21:38:48 ...: [ 166.524041] 1: w=1 pa=2 pr=5 m=2 a=2 r=7 op1=0 op2=0 21:38:48 ...: [ 166.524050] 4: w=2 pa=2 pr=5 m=2 a=2 r=7 op1=0 op2=0 21:38:48 ...: [ 166.524056] 5: w=3 pa=2 pr=5 m=2 a=2 r=7 op1=0 op2=0 21:38:48 ...: [ 166.524062] 6: w=4 pa=2 pr=5 m=2 a=2 r=7 op1=0 op2=0 21:38:48 ...: [ 166.524068] 0: w=5 pa=2 pr=5 m=2 a=2 r=7 op1=0 op2=0 21:38:48 ...: [ 166.524073] 3: w=6 pa=2 pr=5 m=2 a=2 r=7 op1=0 op2=0 21:38:48 ...: [ 166.524079] raid5: raid level 6 set md0 active with 6 out of 7 devices, algorithm 2 21:38:48 ...: [ 166.524519] RAID5 conf printout: 21:38:48 ...: [ 166.524523] --- rd:7 wd:6 21:38:48 ...: [ 166.524528] disk 0, o:1, dev:sdd1 21:38:48 ...: [ 166.524532] disk 1, o:1, dev:sdb1 21:38:48 ...: [ 166.524537] disk 3, o:1, dev:sdc1 21:38:48 ...: [ 166.524541] disk 4, o:1, dev:sdg1 21:38:48 ...: [ 166.524545] disk 5, o:1, dev:sdf1 21:38:48 ...: [ 166.524550] disk 6, o:1, dev:sde1 21:38:48 ...: [ 166.524553] ...ok start reshape thread 21:38:48 ...: [ 166.524727] md0: detected capacity change from 0 to 2999995858944 21:38:48 ...: [ 166.524735] md: reshape of RAID array md0 21:38:48 ...: [ 166.524740] md: minimum _guaranteed_ speed: 1000 KB/sec/disk. 21:38:48 ...: [ 166.524745] md: using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for reshape. 21:38:48 ...: [ 166.524756] md: using 128k window, over a total of 976561152 blocks. 21:39:05 ...: [ 166.525013] md0: 21:42:04 ...: [ 362.520063] INFO: task mdadm:1937 blocked for more than 120 seconds. 21:42:04 ...: [ 362.520068] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:42:04 ...: [ 362.520073] mdadm D 00000000ffffffff 0 1937 1 0x00000000 21:42:04 ...: [ 362.520083] ffff88002ef4f5d8 0000000000000082 0000000000015bc0 0000000000015bc0 21:42:04 ...: [ 362.520092] ffff88002eb5b198 ffff88002ef4ffd8 0000000000015bc0 ffff88002eb5ade0 21:42:04 ...: [ 362.520100] 0000000000015bc0 ffff88002ef4ffd8 0000000000015bc0 ffff88002eb5b198 21:42:04 ...: [ 362.520107] Call Trace: 21:42:04 ...: [ 362.520133] [<ffffffffa0224892>] get_active_stripe+0x312/0x3f0 [raid456] 21:42:04 ...: [ 362.520148] [<ffffffff81059ae0>] ? default_wake_function+0x0/0x20 21:42:04 ...: [ 362.520159] [<ffffffffa0228413>] make_request+0x243/0x4b0 [raid456] 21:42:04 ...: [ 362.520169] [<ffffffffa0221a90>] ? release_stripe+0x50/0x70 [raid456] 21:42:04 ...: [ 362.520179] [<ffffffff81084790>] ? autoremove_wake_function+0x0/0x40 21:42:04 ...: [ 362.520188] [<ffffffff81414df0>] md_make_request+0xc0/0x130 21:42:04 ...: [ 362.520194] [<ffffffff81414df0>] ? md_make_request+0xc0/0x130 21:42:04 ...: [ 362.520205] [<ffffffff8129f8c1>] generic_make_request+0x1b1/0x4f0 21:42:04 ...: [ 362.520214] [<ffffffff810f6515>] ? mempool_alloc_slab+0x15/0x20 21:42:04 ...: [ 362.520222] [<ffffffff8116c2ec>] ? alloc_buffer_head+0x1c/0x60 21:42:04 ...: [ 362.520230] [<ffffffff8129fc80>] submit_bio+0x80/0x110 21:42:04 ...: [ 362.520236] [<ffffffff8116c849>] submit_bh+0xf9/0x140 21:42:04 ...: [ 362.520244] [<ffffffff8116f124>] block_read_full_page+0x274/0x3b0 21:42:04 ...: [ 362.520251] [<ffffffff81172c90>] ? blkdev_get_block+0x0/0x70 21:42:04 ...: [ 362.520258] [<ffffffff8110d875>] ? __inc_zone_page_state+0x35/0x40 21:42:04 ...: [ 362.520265] [<ffffffff810f46d8>] ? add_to_page_cache_locked+0xe8/0x160 21:42:04 ...: [ 362.520272] [<ffffffff81173d78>] blkdev_readpage+0x18/0x20 21:42:04 ...: [ 362.520279] [<ffffffff810f484b>] __read_cache_page+0x7b/0xe0 21:42:04 ...: [ 362.520285] [<ffffffff81173d60>] ? blkdev_readpage+0x0/0x20 21:42:04 ...: [ 362.520290] [<ffffffff81173d60>] ? blkdev_readpage+0x0/0x20 21:42:04 ...: [ 362.520297] [<ffffffff810f57dc>] do_read_cache_page+0x3c/0x120 21:42:04 ...: [ 362.520304] [<ffffffff810f5909>] read_cache_page_async+0x19/0x20 21:42:04 ...: [ 362.520310] [<ffffffff810f591e>] read_cache_page+0xe/0x20 21:42:04 ...: [ 362.520317] [<ffffffff811a6cb0>] read_dev_sector+0x30/0xa0 21:42:04 ...: [ 362.520324] [<ffffffff811a7fcd>] amiga_partition+0x6d/0x460 21:42:04 ...: [ 362.520331] [<ffffffff811a7938>] check_partition+0x138/0x190 21:42:04 ...: [ 362.520338] [<ffffffff811a7a7a>] rescan_partitions+0xea/0x2f0 21:42:04 ...: [ 362.520344] [<ffffffff811744c7>] __blkdev_get+0x267/0x3d0 21:42:04 ...: [ 362.520350] [<ffffffff81174650>] ? blkdev_open+0x0/0xc0 21:42:04 ...: [ 362.520356] [<ffffffff81174640>] blkdev_get+0x10/0x20 21:42:04 ...: [ 362.520362] [<ffffffff811746c1>] blkdev_open+0x71/0xc0 21:42:04 ...: [ 362.520369] [<ffffffff811419f3>] __dentry_open+0x113/0x370 21:42:04 ...: [ 362.520377] [<ffffffff81253f8f>] ? security_inode_permission+0x1f/0x30 21:42:04 ...: [ 362.520385] [<ffffffff8114de3f>] ? inode_permission+0xaf/0xd0 21:42:04 ...: [ 362.520391] [<ffffffff81141d67>] nameidata_to_filp+0x57/0x70 21:42:04 ...: [ 362.520398] [<ffffffff8115207a>] do_filp_open+0x2da/0xba0 21:42:04 ...: [ 362.520406] [<ffffffff811134a8>] ? unmap_vmas+0x178/0x310 21:42:04 ...: [ 362.520414] [<ffffffff8115dbfa>] ? alloc_fd+0x10a/0x150 21:42:04 ...: [ 362.520421] [<ffffffff81141769>] do_sys_open+0x69/0x170 21:42:04 ...: [ 362.520428] [<ffffffff811418b0>] sys_open+0x20/0x30 21:42:04 ...: [ 362.520437] [<ffffffff810121b2>] system_call_fastpath+0x16/0x1b 21:42:04 ...: [ 362.520446] INFO: task mdadm:2283 blocked for more than 120 seconds. 21:42:04 ...: [ 362.520450] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:42:04 ...: [ 362.520454] mdadm D 0000000000000000 0 2283 2212 0x00000000 21:42:04 ...: [ 362.520462] ffff88002cca7d98 0000000000000086 0000000000015bc0 0000000000015bc0 21:42:04 ...: [ 362.520470] ffff88002ededf78 ffff88002cca7fd8 0000000000015bc0 ffff88002ededbc0 21:42:04 ...: [ 362.520478] 0000000000015bc0 ffff88002cca7fd8 0000000000015bc0 ffff88002ededf78 21:42:04 ...: [ 362.520485] Call Trace: 21:42:04 ...: [ 362.520495] [<ffffffff81543a97>] __mutex_lock_slowpath+0xf7/0x180 21:42:04 ...: [ 362.520502] [<ffffffff8154397b>] mutex_lock+0x2b/0x50 21:42:04 ...: [ 362.520508] [<ffffffff8117404d>] __blkdev_put+0x3d/0x190 21:42:04 ...: [ 362.520514] [<ffffffff811741b0>] blkdev_put+0x10/0x20 21:42:04 ...: [ 362.520520] [<ffffffff811741f3>] blkdev_close+0x33/0x60 21:42:04 ...: [ 362.520527] [<ffffffff81145375>] __fput+0xf5/0x210 21:42:04 ...: [ 362.520534] [<ffffffff811454b5>] fput+0x25/0x30 21:42:04 ...: [ 362.520540] [<ffffffff811415ad>] filp_close+0x5d/0x90 21:42:04 ...: [ 362.520546] [<ffffffff81141697>] sys_close+0xb7/0x120 21:42:04 ...: [ 362.520553] [<ffffffff810121b2>] system_call_fastpath+0x16/0x1b 21:42:04 ...: [ 362.520559] INFO: task md0_reshape:2287 blocked for more than 120 seconds. 21:42:04 ...: [ 362.520563] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:42:04 ...: [ 362.520567] md0_reshape D ffff88003aee96f0 0 2287 2 0x00000000 21:42:04 ...: [ 362.520575] ffff88003cf05a70 0000000000000046 0000000000015bc0 0000000000015bc0 21:42:04 ...: [ 362.520582] ffff88003aee9aa8 ffff88003cf05fd8 0000000000015bc0 ffff88003aee96f0 21:42:04 ...: [ 362.520590] 0000000000015bc0 ffff88003cf05fd8 0000000000015bc0 ffff88003aee9aa8 21:42:04 ...: [ 362.520597] Call Trace: 21:42:04 ...: [ 362.520608] [<ffffffffa0224892>] get_active_stripe+0x312/0x3f0 [raid456] 21:42:04 ...: [ 362.520616] [<ffffffff81059ae0>] ? default_wake_function+0x0/0x20 21:42:04 ...: [ 362.520626] [<ffffffffa0226f80>] reshape_request+0x4c0/0x9a0 [raid456] 21:42:04 ...: [ 362.520634] [<ffffffff81084790>] ? autoremove_wake_function+0x0/0x40 21:42:04 ...: [ 362.520644] [<ffffffffa022777a>] sync_request+0x31a/0x3a0 [raid456] 21:42:04 ...: [ 362.520651] [<ffffffff81052713>] ? __wake_up+0x53/0x70 21:42:04 ...: [ 362.520658] [<ffffffff814156b1>] md_do_sync+0x621/0xbb0 21:42:04 ...: [ 362.520668] [<ffffffff810387b9>] ? default_spin_lock_flags+0x9/0x10 21:42:04 ...: [ 362.520675] [<ffffffff8141640c>] md_thread+0x5c/0x130 21:42:04 ...: [ 362.520681] [<ffffffff81084790>] ? autoremove_wake_function+0x0/0x40 21:42:04 ...: [ 362.520688] [<ffffffff814163b0>] ? md_thread+0x0/0x130 21:42:04 ...: [ 362.520694] [<ffffffff81084416>] kthread+0x96/0xa0 21:42:04 ...: [ 362.520701] [<ffffffff810131ea>] child_rip+0xa/0x20 21:42:04 ...: [ 362.520707] [<ffffffff81084380>] ? kthread+0x0/0xa0 21:42:04 ...: [ 362.520713] [<ffffffff810131e0>] ? child_rip+0x0/0x20 21:42:04 ...: [ 362.520718] INFO: task mdadm:2288 blocked for more than 120 seconds. 21:42:04 ...: [ 362.520721] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:42:04 ...: [ 362.520725] mdadm D 0000000000000000 0 2288 1 0x00000000 21:42:04 ...: [ 362.520733] ffff88002cca9c18 0000000000000086 0000000000015bc0 0000000000015bc0 21:42:04 ...: [ 362.520741] ffff88003aee83b8 ffff88002cca9fd8 0000000000015bc0 ffff88003aee8000 21:42:04 ...: [ 362.520748] 0000000000015bc0 ffff88002cca9fd8 0000000000015bc0 ffff88003aee83b8 21:42:04 ...: [ 362.520755] Call Trace: 21:42:04 ...: [ 362.520763] [<ffffffff81543a97>] __mutex_lock_slowpath+0xf7/0x180 21:42:04 ...: [ 362.520771] [<ffffffff812a6d50>] ? exact_match+0x0/0x10 21:42:04 ...: [ 362.520777] [<ffffffff8154397b>] mutex_lock+0x2b/0x50 21:42:04 ...: [ 362.520783] [<ffffffff811742c8>] __blkdev_get+0x68/0x3d0 21:42:04 ...: [ 362.520790] [<ffffffff81174650>] ? blkdev_open+0x0/0xc0 21:42:04 ...: [ 362.520795] [<ffffffff81174640>] blkdev_get+0x10/0x20 21:42:04 ...: [ 362.520801] [<ffffffff811746c1>] blkdev_open+0x71/0xc0 21:42:04 ...: [ 362.520808] [<ffffffff811419f3>] __dentry_open+0x113/0x370 21:42:04 ...: [ 362.520815] [<ffffffff81253f8f>] ? security_inode_permission+0x1f/0x30 21:42:04 ...: [ 362.520821] [<ffffffff8114de3f>] ? inode_permission+0xaf/0xd0 21:42:04 ...: [ 362.520828] [<ffffffff81141d67>] nameidata_to_filp+0x57/0x70 21:42:04 ...: [ 362.520834] [<ffffffff8115207a>] do_filp_open+0x2da/0xba0 21:42:04 ...: [ 362.520841] [<ffffffff810ff0e1>] ? lru_cache_add_lru+0x21/0x40 21:42:04 ...: [ 362.520848] [<ffffffff8111109c>] ? do_anonymous_page+0x11c/0x330 21:42:04 ...: [ 362.520855] [<ffffffff81115d5f>] ? handle_mm_fault+0x31f/0x3c0 21:42:04 ...: [ 362.520862] [<ffffffff8115dbfa>] ? alloc_fd+0x10a/0x150 21:42:04 ...: [ 362.520868] [<ffffffff81141769>] do_sys_open+0x69/0x170 21:42:04 ...: [ 362.520874] [<ffffffff811418b0>] sys_open+0x20/0x30 21:42:04 ...: [ 362.520882] [<ffffffff810121b2>] system_call_fastpath+0x16/0x1b 21:44:04 ...: [ 482.520065] INFO: task mdadm:1937 blocked for more than 120 seconds. 21:44:04 ...: [ 482.520071] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:44:04 ...: [ 482.520077] mdadm D 00000000ffffffff 0 1937 1 0x00000000 21:44:04 ...: [ 482.520087] ffff88002ef4f5d8 0000000000000082 0000000000015bc0 0000000000015bc0 21:44:04 ...: [ 482.520096] ffff88002eb5b198 ffff88002ef4ffd8 0000000000015bc0 ffff88002eb5ade0 21:44:04 ...: [ 482.520104] 0000000000015bc0 ffff88002ef4ffd8 0000000000015bc0 ffff88002eb5b198 21:44:04 ...: [ 482.520112] Call Trace: 21:44:04 ...: [ 482.520139] [<ffffffffa0224892>] get_active_stripe+0x312/0x3f0 [raid456] 21:44:04 ...: [ 482.520154] [<ffffffff81059ae0>] ? default_wake_function+0x0/0x20 21:44:04 ...: [ 482.520165] [<ffffffffa0228413>] make_request+0x243/0x4b0 [raid456] 21:44:04 ...: [ 482.520175] [<ffffffffa0221a90>] ? release_stripe+0x50/0x70 [raid456] 21:44:04 ...: [ 482.520185] [<ffffffff81084790>] ? autoremove_wake_function+0x0/0x40 21:44:04 ...: [ 482.520194] [<ffffffff81414df0>] md_make_request+0xc0/0x130 21:44:04 ...: [ 482.520201] [<ffffffff81414df0>] ? md_make_request+0xc0/0x130 21:44:04 ...: [ 482.520212] [<ffffffff8129f8c1>] generic_make_request+0x1b1/0x4f0 21:44:04 ...: [ 482.520221] [<ffffffff810f6515>] ? mempool_alloc_slab+0x15/0x20 21:44:04 ...: [ 482.520229] [<ffffffff8116c2ec>] ? alloc_buffer_head+0x1c/0x60 21:44:04 ...: [ 482.520237] [<ffffffff8129fc80>] submit_bio+0x80/0x110 21:44:04 ...: [ 482.520244] [<ffffffff8116c849>] submit_bh+0xf9/0x140 21:44:04 ...: [ 482.520252] [<ffffffff8116f124>] block_read_full_page+0x274/0x3b0 21:44:04 ...: [ 482.520258] [<ffffffff81172c90>] ? blkdev_get_block+0x0/0x70 21:44:04 ...: [ 482.520266] [<ffffffff8110d875>] ? __inc_zone_page_state+0x35/0x40 21:44:04 ...: [ 482.520273] [<ffffffff810f46d8>] ? add_to_page_cache_locked+0xe8/0x160 21:44:04 ...: [ 482.520280] [<ffffffff81173d78>] blkdev_readpage+0x18/0x20 21:44:04 ...: [ 482.520286] [<ffffffff810f484b>] __read_cache_page+0x7b/0xe0 21:44:04 ...: [ 482.520293] [<ffffffff81173d60>] ? blkdev_readpage+0x0/0x20 21:44:04 ...: [ 482.520299] [<ffffffff81173d60>] ? blkdev_readpage+0x0/0x20 21:44:04 ...: [ 482.520306] [<ffffffff810f57dc>] do_read_cache_page+0x3c/0x120 21:44:04 ...: [ 482.520313] [<ffffffff810f5909>] read_cache_page_async+0x19/0x20 21:44:04 ...: [ 482.520319] [<ffffffff810f591e>] read_cache_page+0xe/0x20 21:44:04 ...: [ 482.520327] [<ffffffff811a6cb0>] read_dev_sector+0x30/0xa0 21:44:04 ...: [ 482.520334] [<ffffffff811a7fcd>] amiga_partition+0x6d/0x460 21:44:04 ...: [ 482.520341] [<ffffffff811a7938>] check_partition+0x138/0x190 21:44:04 ...: [ 482.520348] [<ffffffff811a7a7a>] rescan_partitions+0xea/0x2f0 21:44:04 ...: [ 482.520355] [<ffffffff811744c7>] __blkdev_get+0x267/0x3d0 21:44:04 ...: [ 482.520361] [<ffffffff81174650>] ? blkdev_open+0x0/0xc0 21:44:04 ...: [ 482.520367] [<ffffffff81174640>] blkdev_get+0x10/0x20 21:44:04 ...: [ 482.520373] [<ffffffff811746c1>] blkdev_open+0x71/0xc0 21:44:04 ...: [ 482.520380] [<ffffffff811419f3>] __dentry_open+0x113/0x370 21:44:04 ...: [ 482.520388] [<ffffffff81253f8f>] ? security_inode_permission+0x1f/0x30 21:44:04 ...: [ 482.520396] [<ffffffff8114de3f>] ? inode_permission+0xaf/0xd0 21:44:04 ...: [ 482.520403] [<ffffffff81141d67>] nameidata_to_filp+0x57/0x70 21:44:04 ...: [ 482.520410] [<ffffffff8115207a>] do_filp_open+0x2da/0xba0 21:44:04 ...: [ 482.520417] [<ffffffff811134a8>] ? unmap_vmas+0x178/0x310 21:44:04 ...: [ 482.520426] [<ffffffff8115dbfa>] ? alloc_fd+0x10a/0x150 21:44:04 ...: [ 482.520432] [<ffffffff81141769>] do_sys_open+0x69/0x170 21:44:04 ...: [ 482.520438] [<ffffffff811418b0>] sys_open+0x20/0x30 21:44:04 ...: [ 482.520447] [<ffffffff810121b2>] system_call_fastpath+0x16/0x1b 21:44:04 ...: [ 482.520458] INFO: task mdadm:2283 blocked for more than 120 seconds. 21:44:04 ...: [ 482.520462] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:44:04 ...: [ 482.520467] mdadm D 0000000000000000 0 2283 2212 0x00000000 21:44:04 ...: [ 482.520475] ffff88002cca7d98 0000000000000086 0000000000015bc0 0000000000015bc0 21:44:04 ...: [ 482.520483] ffff88002ededf78 ffff88002cca7fd8 0000000000015bc0 ffff88002ededbc0 21:44:04 ...: [ 482.520490] 0000000000015bc0 ffff88002cca7fd8 0000000000015bc0 ffff88002ededf78 21:44:04 ...: [ 482.520498] Call Trace: 21:44:04 ...: [ 482.520508] [<ffffffff81543a97>] __mutex_lock_slowpath+0xf7/0x180 21:44:04 ...: [ 482.520515] [<ffffffff8154397b>] mutex_lock+0x2b/0x50 21:44:04 ...: [ 482.520521] [<ffffffff8117404d>] __blkdev_put+0x3d/0x190 21:44:04 ...: [ 482.520527] [<ffffffff811741b0>] blkdev_put+0x10/0x20 21:44:04 ...: [ 482.520533] [<ffffffff811741f3>] blkdev_close+0x33/0x60 21:44:04 ...: [ 482.520541] [<ffffffff81145375>] __fput+0xf5/0x210 21:44:04 ...: [ 482.520547] [<ffffffff811454b5>] fput+0x25/0x30 21:44:04 ...: [ 482.520554] [<ffffffff811415ad>] filp_close+0x5d/0x90 21:44:04 ...: [ 482.520560] [<ffffffff81141697>] sys_close+0xb7/0x120 21:44:04 ...: [ 482.520568] [<ffffffff810121b2>] system_call_fastpath+0x16/0x1b 21:44:04 ...: [ 482.520574] INFO: task md0_reshape:2287 blocked for more than 120 seconds. 21:44:04 ...: [ 482.520578] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:44:04 ...: [ 482.520582] md0_reshape D ffff88003aee96f0 0 2287 2 0x00000000 21:44:04 ...: [ 482.520590] ffff88003cf05a70 0000000000000046 0000000000015bc0 0000000000015bc0 21:44:04 ...: [ 482.520597] ffff88003aee9aa8 ffff88003cf05fd8 0000000000015bc0 ffff88003aee96f0 21:44:04 ...: [ 482.520605] 0000000000015bc0 ffff88003cf05fd8 0000000000015bc0 ffff88003aee9aa8 21:44:04 ...: [ 482.520612] Call Trace: 21:44:04 ...: [ 482.520623] [<ffffffffa0224892>] get_active_stripe+0x312/0x3f0 [raid456] 21:44:04 ...: [ 482.520633] [<ffffffff81059ae0>] ? default_wake_function+0x0/0x20 21:44:04 ...: [ 482.520643] [<ffffffffa0226f80>] reshape_request+0x4c0/0x9a0 [raid456] 21:44:04 ...: [ 482.520651] [<ffffffff81084790>] ? autoremove_wake_function+0x0/0x40 21:44:04 ...: [ 482.520661] [<ffffffffa022777a>] sync_request+0x31a/0x3a0 [raid456] 21:44:04 ...: [ 482.520668] [<ffffffff81052713>] ? __wake_up+0x53/0x70 21:44:04 ...: [ 482.520675] [<ffffffff814156b1>] md_do_sync+0x621/0xbb0 21:44:04 ...: [ 482.520685] [<ffffffff810387b9>] ? default_spin_lock_flags+0x9/0x10 21:44:04 ...: [ 482.520692] [<ffffffff8141640c>] md_thread+0x5c/0x130 21:44:04 ...: [ 482.520699] [<ffffffff81084790>] ? autoremove_wake_function+0x0/0x40 21:44:04 ...: [ 482.520705] [<ffffffff814163b0>] ? md_thread+0x0/0x130 21:44:04 ...: [ 482.520711] [<ffffffff81084416>] kthread+0x96/0xa0 21:44:04 ...: [ 482.520718] [<ffffffff810131ea>] child_rip+0xa/0x20 21:44:04 ...: [ 482.520725] [<ffffffff81084380>] ? kthread+0x0/0xa0 21:44:04 ...: [ 482.520730] [<ffffffff810131e0>] ? child_rip+0x0/0x20 21:44:04 ...: [ 482.520735] INFO: task mdadm:2288 blocked for more than 120 seconds. 21:44:04 ...: [ 482.520739] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:44:04 ...: [ 482.520743] mdadm D 0000000000000000 0 2288 1 0x00000000 21:44:04 ...: [ 482.520751] ffff88002cca9c18 0000000000000086 0000000000015bc0 0000000000015bc0 21:44:04 ...: [ 482.520759] ffff88003aee83b8 ffff88002cca9fd8 0000000000015bc0 ffff88003aee8000 21:44:04 ...: [ 482.520767] 0000000000015bc0 ffff88002cca9fd8 0000000000015bc0 ffff88003aee83b8 21:44:04 ...: [ 482.520774] Call Trace: 21:44:04 ...: [ 482.520782] [<ffffffff81543a97>] __mutex_lock_slowpath+0xf7/0x180 21:44:04 ...: [ 482.520790] [<ffffffff812a6d50>] ? exact_match+0x0/0x10 21:44:04 ...: [ 482.520797] [<ffffffff8154397b>] mutex_lock+0x2b/0x50 21:44:04 ...: [ 482.520804] [<ffffffff811742c8>] __blkdev_get+0x68/0x3d0 21:44:04 ...: [ 482.520810] [<ffffffff81174650>] ? blkdev_open+0x0/0xc0 21:44:04 ...: [ 482.520816] [<ffffffff81174640>] blkdev_get+0x10/0x20 21:44:04 ...: [ 482.520822] [<ffffffff811746c1>] blkdev_open+0x71/0xc0 21:44:04 ...: [ 482.520829] [<ffffffff811419f3>] __dentry_open+0x113/0x370 21:44:04 ...: [ 482.520837] [<ffffffff81253f8f>] ? security_inode_permission+0x1f/0x30 21:44:04 ...: [ 482.520843] [<ffffffff8114de3f>] ? inode_permission+0xaf/0xd0 21:44:04 ...: [ 482.520850] [<ffffffff81141d67>] nameidata_to_filp+0x57/0x70 21:44:04 ...: [ 482.520857] [<ffffffff8115207a>] do_filp_open+0x2da/0xba0 21:44:04 ...: [ 482.520864] [<ffffffff810ff0e1>] ? lru_cache_add_lru+0x21/0x40 21:44:04 ...: [ 482.520871] [<ffffffff8111109c>] ? do_anonymous_page+0x11c/0x330 21:44:04 ...: [ 482.520878] [<ffffffff81115d5f>] ? handle_mm_fault+0x31f/0x3c0 21:44:04 ...: [ 482.520885] [<ffffffff8115dbfa>] ? alloc_fd+0x10a/0x150 21:44:04 ...: [ 482.520891] [<ffffffff81141769>] do_sys_open+0x69/0x170 21:44:04 ...: [ 482.520897] [<ffffffff811418b0>] sys_open+0x20/0x30 21:44:04 ...: [ 482.520905] [<ffffffff810121b2>] system_call_fastpath+0x16/0x1b 21:46:04 ...: [ 602.520053] INFO: task mdadm:1937 blocked for more than 120 seconds. 21:46:04 ...: [ 602.520059] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:46:04 ...: [ 602.520065] mdadm D 00000000ffffffff 0 1937 1 0x00000000 21:46:04 ...: [ 602.520075] ffff88002ef4f5d8 0000000000000082 0000000000015bc0 0000000000015bc0 21:46:04 ...: [ 602.520084] ffff88002eb5b198 ffff88002ef4ffd8 0000000000015bc0 ffff88002eb5ade0 21:46:04 ...: [ 602.520091] 0000000000015bc0 ffff88002ef4ffd8 0000000000015bc0 ffff88002eb5b198 21:46:04 ...: [ 602.520099] Call Trace: 21:46:04 ...: [ 602.520127] [<ffffffffa0224892>] get_active_stripe+0x312/0x3f0 [raid456] 21:46:04 ...: [ 602.520142] [<ffffffff81059ae0>] ? default_wake_function+0x0/0x20 21:46:04 ...: [ 602.520153] [<ffffffffa0228413>] make_request+0x243/0x4b0 [raid456] 21:46:04 ...: [ 602.520162] [<ffffffffa0221a90>] ? release_stripe+0x50/0x70 [raid456] 21:46:04 ...: [ 602.520171] [<ffffffff81084790>] ? autoremove_wake_function+0x0/0x40 21:46:04 ...: [ 602.520180] [<ffffffff81414df0>] md_make_request+0xc0/0x130 21:46:04 ...: [ 602.520187] [<ffffffff81414df0>] ? md_make_request+0xc0/0x130 21:46:04 ...: [ 602.520197] [<ffffffff8129f8c1>] generic_make_request+0x1b1/0x4f0 21:46:04 ...: [ 602.520206] [<ffffffff810f6515>] ? mempool_alloc_slab+0x15/0x20 21:46:04 ...: [ 602.520215] [<ffffffff8116c2ec>] ? alloc_buffer_head+0x1c/0x60 21:46:04 ...: [ 602.520222] [<ffffffff8129fc80>] submit_bio+0x80/0x110 21:46:04 ...: [ 602.520229] [<ffffffff8116c849>] submit_bh+0xf9/0x140 21:46:04 ...: [ 602.520237] [<ffffffff8116f124>] block_read_full_page+0x274/0x3b0 21:46:04 ...: [ 602.520244] [<ffffffff81172c90>] ? blkdev_get_block+0x0/0x70 21:46:04 ...: [ 602.520252] [<ffffffff8110d875>] ? __inc_zone_page_state+0x35/0x40 21:46:04 ...: [ 602.520259] [<ffffffff810f46d8>] ? add_to_page_cache_locked+0xe8/0x160 21:46:04 ...: [ 602.520266] [<ffffffff81173d78>] blkdev_readpage+0x18/0x20 21:46:04 ...: [ 602.520273] [<ffffffff810f484b>] __read_cache_page+0x7b/0xe0 21:46:04 ...: [ 602.520279] [<ffffffff81173d60>] ? blkdev_readpage+0x0/0x20 21:46:04 ...: [ 602.520285] [<ffffffff81173d60>] ? blkdev_readpage+0x0/0x20 21:46:04 ...: [ 602.520292] [<ffffffff810f57dc>] do_read_cache_page+0x3c/0x120 21:46:04 ...: [ 602.520300] [<ffffffff810f5909>] read_cache_page_async+0x19/0x20 21:46:04 ...: [ 602.520306] [<ffffffff810f591e>] read_cache_page+0xe/0x20 21:46:04 ...: [ 602.520314] [<ffffffff811a6cb0>] read_dev_sector+0x30/0xa0 21:46:04 ...: [ 602.520321] [<ffffffff811a7fcd>] amiga_partition+0x6d/0x460 21:46:04 ...: [ 602.520328] [<ffffffff811a7938>] check_partition+0x138/0x190 21:46:04 ...: [ 602.520335] [<ffffffff811a7a7a>] rescan_partitions+0xea/0x2f0 21:46:04 ...: [ 602.520342] [<ffffffff811744c7>] __blkdev_get+0x267/0x3d0 21:46:04 ...: [ 602.520348] [<ffffffff81174650>] ? blkdev_open+0x0/0xc0 21:46:04 ...: [ 602.520354] [<ffffffff81174640>] blkdev_get+0x10/0x20 21:46:04 ...: [ 602.520359] [<ffffffff811746c1>] blkdev_open+0x71/0xc0 21:46:04 ...: [ 602.520367] [<ffffffff811419f3>] __dentry_open+0x113/0x370 21:46:04 ...: [ 602.520375] [<ffffffff81253f8f>] ? security_inode_permission+0x1f/0x30 21:46:04 ...: [ 602.520383] [<ffffffff8114de3f>] ? inode_permission+0xaf/0xd0 21:46:04 ...: [ 602.520390] [<ffffffff81141d67>] nameidata_to_filp+0x57/0x70 21:46:04 ...: [ 602.520397] [<ffffffff8115207a>] do_filp_open+0x2da/0xba0 21:46:04 ...: [ 602.520404] [<ffffffff811134a8>] ? unmap_vmas+0x178/0x310 21:46:04 ...: [ 602.520413] [<ffffffff8115dbfa>] ? alloc_fd+0x10a/0x150 21:46:04 ...: [ 602.520419] [<ffffffff81141769>] do_sys_open+0x69/0x170 21:46:04 ...: [ 602.520425] [<ffffffff811418b0>] sys_open+0x20/0x30 21:46:04 ...: [ 602.520434] [<ffffffff810121b2>] system_call_fastpath+0x16/0x1b 21:46:04 ...: [ 602.520443] INFO: task mdadm:2283 blocked for more than 120 seconds. 21:46:04 ...: [ 602.520447] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 21:46:04 ...: [ 602.520451] mdadm D 0000000000000000 0 2283 2212 0x00000000 21:46:04 ...: [ 602.520460] ffff88002cca7d98 0000000000000086 0000000000015bc0 0000000000015bc0 21:46:04 ...: [ 602.520468] ffff88002ededf78 ffff88002cca7fd8 0000000000015bc0 ffff88002ededbc0 21:46:04 ...: [ 602.520475] 0000000000015bc0 ffff88002cca7fd8 0000000000015bc0 ffff88002ededf78 21:46:04 ...: [ 602.520483] Call Trace: 21:46:04 ...: [ 602.520492] [<ffffffff81543a97>] __mutex_lock_slowpath+0xf7/0x180 21:46:04 ...: [ 602.520500] [<ffffffff8154397b>] mutex_lock+0x2b/0x50 21:46:04 ...: [ 602.520506] [<ffffffff8117404d>] __blkdev_put+0x3d/0x190 21:46:04 ...: [ 602.520512] [<ffffffff811741b0>] blkdev_put+0x10/0x20 21:46:04 ...: [ 602.520518] [<ffffffff811741f3>] blkdev_close+0x33/0x60 21:46:04 ...: [ 602.520526] [<ffffffff81145375>] __fput+0xf5/0x210 21:46:04 ...: [ 602.520533] [<ffffffff811454b5>] fput+0x25/0x30 21:46:04 ...: [ 602.520539] [<ffffffff811415ad>] filp_close+0x5d/0x90 21:46:04 ...: [ 602.520545] [<ffffffff81141697>] sys_close+0xb7/0x120 21:46:04 ...: [ 602.520552] [<ffffffff810121b2>] system_call_fastpath+0x16/0x1b

  Read the article

• How can I resolve Hibernate 3's ConstraintViolationException when updating a Persistent Entity's Col

  - by Tim Visher

  I'm trying to discover why two nearly identical class sets are behaving different from Hibernate 3's perspective. I'm fairly new to Hibernate in general and I'm hoping I'm missing something fairly obvious about the mappings or timing issues or something along those lines but I spent the whole day yesterday staring at the two sets and any differences that would lead to one being able to be persisted and the other not completely escaped me. I appologize in advance for the length of this question but it all hinges around some pretty specific implementation details. I have the following class mapped with Annotations and managed by Hibernate 3.? (if the specific specific version turns out to be pertinent, I'll figure out what it is). Java version is 1.6. ... @Embeddable public class JobStateChange implements Comparable<JobStateChange> { @Temporal(TemporalType.TIMESTAMP) @Column(nullable = false) private Date date; @Enumerated(EnumType.STRING) @Column(nullable = false, length = JobState.FIELD_LENGTH) private JobState state; @ManyToOne(fetch = FetchType.LAZY) @JoinColumn(name = "acting_user_id", nullable = false) private User actingUser; public JobStateChange() { } @Override public int compareTo(final JobStateChange o) { return this.date.compareTo(o.date); } @Override public boolean equals(final Object obj) { if (this == obj) { return true; } else if (!(obj instanceof JobStateChange)) { return false; } JobStateChange candidate = (JobStateChange) obj; return this.state == candidate.state && this.actingUser.equals(candidate.getUser()) && this.date.equals(candidate.getDate()); } @Override public int hashCode() { return this.state.hashCode() + this.actingUser.hashCode() + this.date.hashCode(); } } It is mapped as a Hibernate CollectionOfElements in the class Job as follows: ... @Entity @Table( name = "job", uniqueConstraints = { @UniqueConstraint( columnNames = { "agency", //Job Name "payment_type", //Job Name "payment_file", //Job Name "date_of_payment", "payment_control_number", "truck_number" }) }) public class Job implements Serializable { private static final long serialVersionUID = -1131729422634638834L; ... @org.hibernate.annotations.CollectionOfElements @JoinTable(name = "job_state", joinColumns = @JoinColumn(name = "job_id")) @Sort(type = SortType.NATURAL) private final SortedSet<JobStateChange> stateChanges = new TreeSet<JobStateChange>(); ... public void advanceState( final User actor, final Date date) { JobState nextState; LOGGER.debug("Current state of {} is {}.", this, this.getCurrentState()); if (null == this.currentState) { nextState = JobState.BEGINNING; } else { if (!this.isAdvanceable()) { throw new IllegalAdvancementException(this.currentState.illegalAdvancementStateMessage); } if (this.currentState.isDivergent()) { nextState = this.currentState.getNextState(this); } else { nextState = this.currentState.getNextState(); } } JobStateChange stateChange = new JobStateChange(nextState, actor, date); this.setCurrentState(stateChange.getState()); this.stateChanges.add(stateChange); LOGGER.debug("Advanced {} to {}", this, this.getCurrentState()); } private void setCurrentState(final JobState jobState) { this.currentState = jobState; } boolean isAdvanceable() { return this.getCurrentState().isAdvanceable(this); } ... @Override public boolean equals(final Object obj) { if (obj == this) { return true; } else if (!(obj instanceof Job)) { return false; } Job otherJob = (Job) obj; return this.getName().equals(otherJob.getName()) && this.getDateOfPayment().equals(otherJob.getDateOfPayment()) && this.getPaymentControlNumber().equals(otherJob.getPaymentControlNumber()) && this.getTruckNumber().equals(otherJob.getTruckNumber()); } @Override public int hashCode() { return this.getName().hashCode() + this.getDateOfPayment().hashCode() + this.getPaymentControlNumber().hashCode() + this.getTruckNumber().hashCode(); } ... } The purpose of JobStateChange is to record when the Job moves through a series of State Changes that are outline in JobState as enums which know about advancement and decrement rules. The interface used to advance Jobs through a series of states is to call Job.advanceState() with a Date and a User. If the Job is advanceable according to rules coded in the enum, then a new StateChange is added to the SortedSet and everyone's happy. If not, an IllegalAdvancementException is thrown. The DDL this generates is as follows: ... drop table job; drop table job_state; ... create table job ( id bigint generated by default as identity, current_state varchar(25), date_of_payment date not null, beginningCheckNumber varchar(8) not null, item_count integer, agency varchar(10) not null, payment_file varchar(25) not null, payment_type varchar(25) not null, endingCheckNumber varchar(8) not null, payment_control_number varchar(4) not null, truck_number varchar(255) not null, wrapping_system_type varchar(15) not null, printer_id bigint, primary key (id), unique (agency, payment_type, payment_file, date_of_payment, payment_control_number, truck_number) ); create table job_state ( job_id bigint not null, acting_user_id bigint not null, date timestamp not null, state varchar(25) not null, primary key (job_id, acting_user_id, date, state) ); ... alter table job add constraint FK19BBD12FB9D70 foreign key (printer_id) references printer; alter table job_state add constraint FK57C2418FED1F0D21 foreign key (acting_user_id) references app_user; alter table job_state add constraint FK57C2418FABE090B3 foreign key (job_id) references job; ... The database is seeded with the following data prior to running tests ... insert into job (id, agency, payment_type, payment_file, payment_control_number, date_of_payment, beginningCheckNumber, endingCheckNumber, item_count, current_state, printer_id, wrapping_system_type, truck_number) values (-3, 'RRB', 'Monthly', 'Monthly','4501','1998-12-01 08:31:16' , '00000001','00040000', 40000, 'UNASSIGNED', null, 'KERN', '02'); insert into job_state (job_id, acting_user_id, date, state) values (-3, -1, '1998-11-30 08:31:17', 'UNASSIGNED'); ... After the database schema is automatically generated and rebuilt by the Hibernate tool. The following test runs fine up until the call to Session.flush() ... @ContextConfiguration(locations = { "/applicationContext-data.xml", "/applicationContext-service.xml" }) public class JobDaoIntegrationTest extends AbstractTransactionalJUnit4SpringContextTests { @Autowired private JobDao jobDao; @Autowired private SessionFactory sessionFactory; @Autowired private UserService userService; @Autowired private PrinterService printerService; ... @Test public void saveJob_JobAdvancedToAssigned_AllExpectedStateChanges() { //Get an unassigned Job Job job = this.jobDao.getJob(-3L); assertEquals(JobState.UNASSIGNED, job.getCurrentState()); Date advancedToUnassigned = new GregorianCalendar(1998, 10, 30, 8, 31, 17).getTime(); assertEquals(advancedToUnassigned, job.getStateChange(JobState.UNASSIGNED).getDate()); //Satisfy advancement constraints and advance job.setPrinter(this.printerService.getPrinter(-1L)); Date advancedToAssigned = new Date(); job.advanceState( this.userService.getUserByUsername("admin"), advancedToAssigned); assertEquals(JobState.ASSIGNED, job.getCurrentState()); assertEquals(advancedToUnassigned, job.getStateChange(JobState.UNASSIGNED).getDate()); assertEquals(advancedToAssigned, job.getStateChange(JobState.ASSIGNED).getDate()); //Persist to DB this.sessionFactory.getCurrentSession().flush(); ... } ... } The error thrown is SQLCODE=-803, SQLSTATE=23505: could not insert collection rows: [jaci.model.job.Job.stateChanges#-3] org.hibernate.exception.ConstraintViolationException: could not insert collection rows: [jaci.model.job.Job.stateChanges#-3] at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:94) at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66) at org.hibernate.persister.collection.AbstractCollectionPersister.insertRows(AbstractCollectionPersister.java:1416) at org.hibernate.action.CollectionUpdateAction.execute(CollectionUpdateAction.java:86) at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:170) at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321) at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50) at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027) at jaci.dao.JobDaoIntegrationTest.saveJob_JobAdvancedToAssigned_AllExpectedStateChanges(JobDaoIntegrationTest.java:98) at org.springframework.test.context.junit4.SpringTestMethod.invoke(SpringTestMethod.java:160) at org.springframework.test.context.junit4.SpringMethodRoadie.runTestMethod(SpringMethodRoadie.java:233) at org.springframework.test.context.junit4.SpringMethodRoadie$RunBeforesThenTestThenAfters.run(SpringMethodRoadie.java:333) at org.springframework.test.context.junit4.SpringMethodRoadie.runWithRepetitions(SpringMethodRoadie.java:217) at org.springframework.test.context.junit4.SpringMethodRoadie.runTest(SpringMethodRoadie.java:197) at org.springframework.test.context.junit4.SpringMethodRoadie.run(SpringMethodRoadie.java:143) at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.invokeTestMethod(SpringJUnit4ClassRunner.java:160) at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:97) Caused by: com.ibm.db2.jcc.b.lm: DB2 SQL Error: SQLCODE=-803, SQLSTATE=23505, SQLERRMC=1;ACI_APP.JOB_STATE, DRIVER=3.50.152 at com.ibm.db2.jcc.b.wc.a(wc.java:575) at com.ibm.db2.jcc.b.wc.a(wc.java:57) at com.ibm.db2.jcc.b.wc.a(wc.java:126) at com.ibm.db2.jcc.b.tk.b(tk.java:1593) at com.ibm.db2.jcc.b.tk.c(tk.java:1576) at com.ibm.db2.jcc.t4.db.k(db.java:353) at com.ibm.db2.jcc.t4.db.a(db.java:59) at com.ibm.db2.jcc.t4.t.a(t.java:50) at com.ibm.db2.jcc.t4.tb.b(tb.java:200) at com.ibm.db2.jcc.b.uk.Gb(uk.java:2355) at com.ibm.db2.jcc.b.uk.e(uk.java:3129) at com.ibm.db2.jcc.b.uk.zb(uk.java:568) at com.ibm.db2.jcc.b.uk.executeUpdate(uk.java:551) at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:46) at org.hibernate.persister.collection.AbstractCollectionPersister.insertRows(AbstractCollectionPersister.java:1389) Therein lies my problem… A nearly identical Class set (in fact, so identical that I've been chomping at the bit to make it a single class that serves both business entities) runs absolutely fine. It is identical except for name. Instead of Job it's Web. Instead of JobStateChange it's WebStateChange. Instead of JobState it's WebState. Both Job and Web's SortedSet of StateChanges are mapped as a Hibernate CollectionOfElements. Both are @Embeddable. Both are SortType.Natural. Both are backed by an Enumeration with some advancement rules in it. And yet when a nearly identical test is run for Web, no issue is discovered and the data flushes fine. For the sake of brevity I won't include all of the Web classes here, but I will include the test and if anyone wants to see the actual sources, I'll include them (just leave a comment). The data seed: insert into web (id, stock_type, pallet, pallet_id, date_received, first_icn, last_icn, shipment_id, current_state) values (-1, 'PF', '0011', 'A', '2008-12-31 08:30:02', '000000001', '000080000', -1, 'UNSTAGED'); insert into web_state (web_id, date, state, acting_user_id) values (-1, '2008-12-31 08:30:03', 'UNSTAGED', -1); The test: ... @ContextConfiguration(locations = { "/applicationContext-data.xml", "/applicationContext-service.xml" }) public class WebDaoIntegrationTest extends AbstractTransactionalJUnit4SpringContextTests { @Autowired private WebDao webDao; @Autowired private UserService userService; @Autowired private SessionFactory sessionFactory; ... @Test public void saveWeb_WebAdvancedToNewState_AllExpectedStateChanges() { Web web = this.webDao.getWeb(-1L); Date advancedToUnstaged = new GregorianCalendar(2008, 11, 31, 8, 30, 3).getTime(); assertEquals(WebState.UNSTAGED, web.getCurrentState()); assertEquals(advancedToUnstaged, web.getState(WebState.UNSTAGED).getDate()); Date advancedToStaged = new Date(); web.advanceState( this.userService.getUserByUsername("admin"), advancedToStaged); this.sessionFactory.getCurrentSession().flush(); web = this.webDao.getWeb(web.getId()); assertEquals( "Web should have moved to STAGED State.", WebState.STAGED, web.getCurrentState()); assertEquals(advancedToUnstaged, web.getState(WebState.UNSTAGED).getDate()); assertEquals(advancedToStaged, web.getState(WebState.STAGED).getDate()); assertNotNull(web.getState(WebState.UNSTAGED)); assertNotNull(web.getState(WebState.STAGED)); } ... } As you can see, I assert that the Web was reconstituted the way I expect, I advance it, flush it to the DB, and then re-get it and verify that the states are as I expect. Everything works perfectly. Not so with Job. A possibly pertinent detail: the reconstitution code works fine if I cease to map JobStateChange.data as a TIMESTAMP and instead as a DATE, and ensure that all of the StateChanges always occur on different Dates. The problem is that this particular business entity can go through many state changes in a single day and so it needs to be sorted by time stamp rather than by date. If I don't do this then I can't sort the StateChanges correctly. That being said, WebStateChange.date is also mapped as a TIMESTAMP and so I again remain absolutely befuddled as to where this error is arising from. I tried to do a fairly thorough job of giving all of the technical details of the implementation but as this particular question is very implementation specific, if I missed anything just let me know in the comments and I'll include it. Thanks so much for your help! UPDATE: Since it turns out to be important to the solution of my problem, I have to include the pertinent bits of the WebStateChange class as well. ... @Embeddable public class WebStateChange implements Comparable<WebStateChange> { @Temporal(TemporalType.TIMESTAMP) @Column(nullable = false) private Date date; @Enumerated(EnumType.STRING) @Column(nullable = false, length = WebState.FIELD_LENGTH) private WebState state; @ManyToOne(fetch = FetchType.LAZY) @JoinColumn(name = "acting_user_id", nullable = false) private User actingUser; ... WebStateChange( final WebState state, final User actingUser, final Date date) { ExceptionUtils.illegalNullArgs(state, actingUser, date); this.state = state; this.actingUser = actingUser; this.date = new Date(date.getTime()); } @Override public int compareTo(final WebStateChange otherStateChange) { return this.date.compareTo(otherStateChange.date); } @Override public boolean equals(final Object candidate) { if (this == candidate) { return true; } else if (!(candidate instanceof WebStateChange)) { return false; } WebStateChange candidateWebState = (WebStateChange) candidate; return this.getState() == candidateWebState.getState() && this.getUser().equals(candidateWebState.getUser()) && this.getDate().equals(candidateWebState.getDate()); } @Override public int hashCode() { return this.getState().hashCode() + this.getUser().hashCode() + this.getDate().hashCode(); } ... }

  Read the article

< Previous Page | 2 3 4 5 6