New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Udev lockup upon dom0 boot #551

Closed
marmarek opened this Issue Mar 8, 2015 · 11 comments

Comments

Projects
None yet
2 participants
@marmarek
Member

marmarek commented Mar 8, 2015

Reported by joanna on 25 Apr 2012 23:29 UTC
Quite regularly my Dom0 boot is hanging for a few minutes on udev. Removing 'quiet' from kernel cmd line doesn't provide more details regarding what's happening during the hangup. However, dmesg reports this (which seems to be related):

[  127.712452] INFO: rcu_sched detected stalls on CPUs/tasks: { 2} (detected by 1, t=15041 jiffies)
[  127.712479] Pid: 2592, comm: block_add_chang Tainted: G         C   3.2.7-3.pvops.qubes.x86_64 #1
[  127.712487] Call Trace:
[  127.712492]  <IRQ>  [print_other_cpu_stall+0x15a/0x1b0
[  127.712522](<ffffffff810c026a>])  [? check_events+0x12/0x20
[  127.712532](<ffffffff8100a072>])  [__rcu_pending+0x73/0x290
[  127.712541](<ffffffff810c0333>])  [rcu_check_callbacks+0x75/0x1b0
[  127.712553](<ffffffff810c05c5>])  [update_process_times+0x43/0x80
[  127.712566](<ffffffff8106c783>])  [tick_sched_timer+0x61/0xb0
[  127.712576](<ffffffff81090221>])  [__run_hrtimer+0x7d/0x1c0
[  127.712586](<ffffffff8108319d>])  [? tick_nohz_handler+0xf0/0xf0
[  127.712596](<ffffffff810901c0>])  [hrtimer_interrupt+0xf6/0x230
[  127.712607](<ffffffff81083556>])  [xen_timer_interrupt+0x27/0x40
[  127.712618](<ffffffff81009e27>])  [handle_irq_event_percpu+0x5d/0x210
[  127.712629](<ffffffff810b8b7d>])  [handle_percpu_irq+0x49/0x70
[  127.712642](<ffffffff810bbd39>])  [__xen_evtchn_do_upcall+0x1b4/0x280
[  127.712653](<ffffffff812a6824>])  [xen_evtchn_do_upcall+0x2a/0x40
[  127.712663](<ffffffff812a733a>])  [xen_do_hypervisor_callback+0x1e/0x30
[  127.712669](<ffffffff814519fe>])  <EOI>  [? hypercall_page+0x22a/0x1000
[  127.712689](<ffffffff8100122a>])  [? hypercall_page+0x22a/0x1000
[  127.712700](<ffffffff8100122a>])  [? xen_force_evtchn_callback+0xd/0x10
[  127.712710](<ffffffff8100987d>])  [? check_events+0x12/0x20
[  127.712720](<ffffffff8100a072>])  [? xen_irq_enable_direct_reloc+0x4/0x4
[  127.712731](<ffffffff8100a019>])  [? finish_task_switch+0x5d/0xc0
[  127.712743](<ffffffff8105358d>])  [? __schedule+0x3a5/0x7a0
[  127.712753](<ffffffff81445595>])  [? schedule+0x3a/0x50
[  127.712763](<ffffffff81445a6a>])  [? schedule_timeout+0x167/0x2b0
[  127.712772](<ffffffff81445e47>])  [? lock_timer_base+0x70/0x70
[  127.712785](<ffffffff8106c6a0>])  [? audit_log_start+0x272/0x360
[  127.712795](<ffffffff810ae852>])  [? try_to_wake_up+0x2b0/0x2b0
[  127.712806](<ffffffff810532b0>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[  127.712817](<ffffffff814478b1>])  [? audit_buffer_free+0x6e/0x90
[  127.712827](<ffffffff810ad65e>])  [? audit_log_exit+0x563/0x950
[  127.712837](<ffffffff810b4873>])  [? audit_syscall_exit+0x254/0x260
[  127.712848](<ffffffff810b5124>])  [<ffffffff8144f884>] ? sysret_audit+0x16/0x20

After this several-minute-long delay, the system boots fine, and all seems to work fine...

Migrated-From: https://wiki.qubes-os.org/ticket/551

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Comment by joanna on 12 May 2012 12:04 UTC
Kind of a subset of #560.

Member

marmarek commented Mar 8, 2015

Comment by joanna on 12 May 2012 12:04 UTC
Kind of a subset of #560.

@marmarek marmarek closed this Mar 8, 2015

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Comment by joanna on 14 Jul 2012 13:51 UTC
Jut got this again.

Dom0 kernel: 3.2.7-6
core: 2.0.34

Key slot 0 unlocked.
                Welcome to Qubes
                Press 'I' to enter interactive startup.
Starting udev: udevd[worker [845](794]:) unexpectedly returned with status 0x0100

udevd[worker [845](794]:) failed while handling '/devices/virtual/block/loop116'

udevd[worker [808](794]:) unexpectedly returned with status 0x0100

udevd[worker [808](794]:) failed while handling '/devices/pci0000:00/0000:00:1f.2/host0/target0:0:0/0:0:0:0/block/sda'

udevd[worker [804](794]:) unexpectedly returned with status 0x0100

udevd[worker [804](794]:) failed while handling '/devices/platform/thinkpad_acpi/input/input8/event8'

udevd[worker [815](794]:) unexpectedly returned with status 0x0100

udevd[worker [815](794]:) failed while handling '/devices/pci0000:00/0000:00:1f.2/host1/target1:0:0/1:0:0:0/block/sr0'

udevd[worker [822](794]:) unexpectedly returned with status 0x0100

udevd[worker [822](794]:) failed while handling '/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.1'

udevd[worker [833](794]:) unexpectedly returned with status 0x0100

udevd[worker [833](794]:) failed while handling '/devices/virtual/block/loop173'

udevd[worker [846](794]:) unexpectedly returned with status 0x0100

udevd[worker [846](794]:) failed while handling '/devices/virtual/block/loop107'

udevd[worker [835](794]:) unexpectedly returned with status 0x0100

udevd[worker [835](794]:) failed while handling '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.9/tty/ttyACM2'

udevd[worker [849](794]:) unexpectedly returned with status 0x0100

udevd[worker [849](794]:) failed while handling '/devices/virtual/block/loop100'

udevd[worker [850](794]:) unexpectedly returned with status 0x0100

udevd[worker [850](794]:) failed while handling '/devices/virtual/block/loop117'

udevd[worker [853](794]:) unexpectedly returned with status 0x0100

udevd[worker [853](794]:) failed while handling '/devices/virtual/block/loop119'

udevd[worker [922](794]:) unexpectedly returned with status 0x0100

udevd[worker [922](794]:) failed while handling '/devices/virtual/block/loop123'

udevd[worker [960](794]:) unexpectedly returned with status 0x0100

udevd[worker [960](794]:) failed while handling '/devices/virtual/block/loop135'

udevd[worker [977](794]:) unexpectedly returned with status 0x0100

udevd[worker [977](794]:) failed while handling '/devices/virtual/block/loop141'

udevd[worker [986](794]:) unexpectedly returned with status 0x0100

udevd[worker [986](794]:) failed while handling '/devices/virtual/block/loop139'

udevd[worker [988](794]:) unexpectedly returned with status 0x0100

udevd[worker [988](794]:) failed while handling '/devices/virtual/block/loop140'

udevd[worker [993](794]:) unexpectedly returned with status 0x0100

udevd[worker [993](794]:) failed while handling '/devices/virtual/block/loop145'

udevd[worker [994](794]:) unexpectedly returned with status 0x0100

udevd[worker [994](794]:) failed while handling '/devices/virtual/block/loop146'

udevd[worker [996](794]:) unexpectedly returned with status 0x0100

udevd[worker [996](794]:) failed while handling '/devices/virtual/block/loop148'

udevd[worker [999](794]:) unexpectedly returned with status 0x0100

udevd[worker [999](794]:) failed while handling '/devices/virtual/block/loop150'

udevd[worker [1008](794]:) unexpectedly returned with status 0x0100

udevd[worker [1008](794]:) failed while handling '/devices/virtual/block/loop155'

udevd[worker [1012](794]:) unexpectedly returned with status 0x0100

udevd[worker [1012](794]:) failed while handling '/devices/virtual/block/loop158'

udevd[worker [1023](794]:) unexpectedly returned with status 0x0100

udevd[worker [1023](794]:) failed while handling '/devices/virtual/block/loop167'

udevd[worker [1028](794]:) unexpectedly returned with status 0x0100

udevd[worker [1028](794]:) failed while handling '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.3/tty/ttyACM1'

udevd[worker [1029](794]:) unexpectedly returned with status 0x0100

udevd[worker [1029](794]:) failed while handling '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.1/tty/ttyACM0'

udevd[worker [824](794]:) unexpectedly returned with status 0x0100

udevd[worker [824](794]:) failed while handling '/devices/platform/thinkpad_acpi/sound/card29'

udevd[worker [828](794]:) unexpectedly returned with status 0x0100

udevd[worker [828](794]:) failed while handling '/devices/virtual/block/loop12'

udevd[worker [841](794]:) unexpectedly returned with status 0x0100

udevd[worker [841](794]:) failed while handling '/devices/virtual/block/loop193'

udevd[worker [857](794]:) unexpectedly returned with status 0x0100

udevd[worker [857](794]:) failed while handling '/devices/virtual/block/loop102'

udevd[worker [1014](794]:) unexpectedly returned with status 0x0100

udevd[worker [1014](794]:) failed while handling '/devices/virtual/block/loop16'

udevd[worker [1016](794]:) unexpectedly returned with status 0x0100

udevd[worker [1016](794]:) failed while handling '/devices/virtual/block/loop160'

udevd[worker [1025](794]:) unexpectedly returned with status 0x0100

udevd[worker [1025](794]:) failed while handling '/devices/virtual/block/loop169'

udevd[worker [805](794]:) unexpectedly returned with status 0x0100

udevd[worker [805](794]:) failed while handling '/devices/pci0000:00/0000:00:1b.0'

udevd[worker [1003](794]:) unexpectedly returned with status 0x0100

udevd[worker [1003](794]:) failed while handling '/devices/virtual/block/loop153'

udevd[worker [961](794]:) unexpectedly returned with status 0x0100

udevd[worker [961](794]:) failed while handling '/devices/virtual/block/loop19'

udevd[worker [842](794]:) unexpectedly returned with status 0x0100

udevd[worker [842](794]:) failed while handling '/devices/virtual/block/loop115'

                                                           [  OK  ]
Setting hostname dom0:                                     [  OK  ]


Member

marmarek commented Mar 8, 2015

Comment by joanna on 14 Jul 2012 13:51 UTC
Jut got this again.

Dom0 kernel: 3.2.7-6
core: 2.0.34

Key slot 0 unlocked.
                Welcome to Qubes
                Press 'I' to enter interactive startup.
Starting udev: udevd[worker [845](794]:) unexpectedly returned with status 0x0100

udevd[worker [845](794]:) failed while handling '/devices/virtual/block/loop116'

udevd[worker [808](794]:) unexpectedly returned with status 0x0100

udevd[worker [808](794]:) failed while handling '/devices/pci0000:00/0000:00:1f.2/host0/target0:0:0/0:0:0:0/block/sda'

udevd[worker [804](794]:) unexpectedly returned with status 0x0100

udevd[worker [804](794]:) failed while handling '/devices/platform/thinkpad_acpi/input/input8/event8'

udevd[worker [815](794]:) unexpectedly returned with status 0x0100

udevd[worker [815](794]:) failed while handling '/devices/pci0000:00/0000:00:1f.2/host1/target1:0:0/1:0:0:0/block/sr0'

udevd[worker [822](794]:) unexpectedly returned with status 0x0100

udevd[worker [822](794]:) failed while handling '/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.1'

udevd[worker [833](794]:) unexpectedly returned with status 0x0100

udevd[worker [833](794]:) failed while handling '/devices/virtual/block/loop173'

udevd[worker [846](794]:) unexpectedly returned with status 0x0100

udevd[worker [846](794]:) failed while handling '/devices/virtual/block/loop107'

udevd[worker [835](794]:) unexpectedly returned with status 0x0100

udevd[worker [835](794]:) failed while handling '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.9/tty/ttyACM2'

udevd[worker [849](794]:) unexpectedly returned with status 0x0100

udevd[worker [849](794]:) failed while handling '/devices/virtual/block/loop100'

udevd[worker [850](794]:) unexpectedly returned with status 0x0100

udevd[worker [850](794]:) failed while handling '/devices/virtual/block/loop117'

udevd[worker [853](794]:) unexpectedly returned with status 0x0100

udevd[worker [853](794]:) failed while handling '/devices/virtual/block/loop119'

udevd[worker [922](794]:) unexpectedly returned with status 0x0100

udevd[worker [922](794]:) failed while handling '/devices/virtual/block/loop123'

udevd[worker [960](794]:) unexpectedly returned with status 0x0100

udevd[worker [960](794]:) failed while handling '/devices/virtual/block/loop135'

udevd[worker [977](794]:) unexpectedly returned with status 0x0100

udevd[worker [977](794]:) failed while handling '/devices/virtual/block/loop141'

udevd[worker [986](794]:) unexpectedly returned with status 0x0100

udevd[worker [986](794]:) failed while handling '/devices/virtual/block/loop139'

udevd[worker [988](794]:) unexpectedly returned with status 0x0100

udevd[worker [988](794]:) failed while handling '/devices/virtual/block/loop140'

udevd[worker [993](794]:) unexpectedly returned with status 0x0100

udevd[worker [993](794]:) failed while handling '/devices/virtual/block/loop145'

udevd[worker [994](794]:) unexpectedly returned with status 0x0100

udevd[worker [994](794]:) failed while handling '/devices/virtual/block/loop146'

udevd[worker [996](794]:) unexpectedly returned with status 0x0100

udevd[worker [996](794]:) failed while handling '/devices/virtual/block/loop148'

udevd[worker [999](794]:) unexpectedly returned with status 0x0100

udevd[worker [999](794]:) failed while handling '/devices/virtual/block/loop150'

udevd[worker [1008](794]:) unexpectedly returned with status 0x0100

udevd[worker [1008](794]:) failed while handling '/devices/virtual/block/loop155'

udevd[worker [1012](794]:) unexpectedly returned with status 0x0100

udevd[worker [1012](794]:) failed while handling '/devices/virtual/block/loop158'

udevd[worker [1023](794]:) unexpectedly returned with status 0x0100

udevd[worker [1023](794]:) failed while handling '/devices/virtual/block/loop167'

udevd[worker [1028](794]:) unexpectedly returned with status 0x0100

udevd[worker [1028](794]:) failed while handling '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.3/tty/ttyACM1'

udevd[worker [1029](794]:) unexpectedly returned with status 0x0100

udevd[worker [1029](794]:) failed while handling '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.1/tty/ttyACM0'

udevd[worker [824](794]:) unexpectedly returned with status 0x0100

udevd[worker [824](794]:) failed while handling '/devices/platform/thinkpad_acpi/sound/card29'

udevd[worker [828](794]:) unexpectedly returned with status 0x0100

udevd[worker [828](794]:) failed while handling '/devices/virtual/block/loop12'

udevd[worker [841](794]:) unexpectedly returned with status 0x0100

udevd[worker [841](794]:) failed while handling '/devices/virtual/block/loop193'

udevd[worker [857](794]:) unexpectedly returned with status 0x0100

udevd[worker [857](794]:) failed while handling '/devices/virtual/block/loop102'

udevd[worker [1014](794]:) unexpectedly returned with status 0x0100

udevd[worker [1014](794]:) failed while handling '/devices/virtual/block/loop16'

udevd[worker [1016](794]:) unexpectedly returned with status 0x0100

udevd[worker [1016](794]:) failed while handling '/devices/virtual/block/loop160'

udevd[worker [1025](794]:) unexpectedly returned with status 0x0100

udevd[worker [1025](794]:) failed while handling '/devices/virtual/block/loop169'

udevd[worker [805](794]:) unexpectedly returned with status 0x0100

udevd[worker [805](794]:) failed while handling '/devices/pci0000:00/0000:00:1b.0'

udevd[worker [1003](794]:) unexpectedly returned with status 0x0100

udevd[worker [1003](794]:) failed while handling '/devices/virtual/block/loop153'

udevd[worker [961](794]:) unexpectedly returned with status 0x0100

udevd[worker [961](794]:) failed while handling '/devices/virtual/block/loop19'

udevd[worker [842](794]:) unexpectedly returned with status 0x0100

udevd[worker [842](794]:) failed while handling '/devices/virtual/block/loop115'

                                                           [  OK  ]
Setting hostname dom0:                                     [  OK  ]


@marmarek marmarek removed the R: duplicate label Mar 8, 2015

@marmarek marmarek reopened this Mar 8, 2015

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Comment by marmarek on 14 Jul 2012 15:02 UTC
Do you have still udev rules, mentioned in #605, removed?

Member

marmarek commented Mar 8, 2015

Comment by marmarek on 14 Jul 2012 15:02 UTC
Do you have still udev rules, mentioned in #605, removed?

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Comment by joanna on 14 Jul 2012 16:16 UTC
Yes, I have no 69-xorg-vmmouse.rules.

Member

marmarek commented Mar 8, 2015

Comment by joanna on 14 Jul 2012 16:16 UTC
Yes, I have no 69-xorg-vmmouse.rules.

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Comment by marmarek on 15 Jul 2012 12:22 UTC
Same as earlier, process list during hang - before above messages (got via sysrq) will be very helpful.

Member

marmarek commented Mar 8, 2015

Comment by marmarek on 15 Jul 2012 12:22 UTC
Same as earlier, process list during hang - before above messages (got via sysrq) will be very helpful.

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Comment by joanna on 20 Jul 2012 13:23 UTC
Tried dozens of times and couldn't reproduce it. Enabled SysRq keys on both my machines, and will reopen when/if ever get this again.

Member

marmarek commented Mar 8, 2015

Comment by joanna on 20 Jul 2012 13:23 UTC
Tried dozens of times and couldn't reproduce it. Enabled SysRq keys on both my machines, and will reopen when/if ever get this again.

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Modified by joanna on 20 Jul 2012 13:24 UTC

Member

marmarek commented Mar 8, 2015

Modified by joanna on 20 Jul 2012 13:24 UTC

@marmarek marmarek added the worksforme label Mar 8, 2015

@marmarek marmarek closed this Mar 8, 2015

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Comment by joanna on 30 Jul 2012 14:46 UTC
I managed to reproduce it, and was able to use SysRq this time. But first, some oopses from dmesg (there is tons of them there, just picked a few common ones):

[   89.208113] udevd           S 0000000000000000     0  1083    794 0x00000080
[   89.208123]  ffff8801d85e18d8 0000000000000282 0000000000000000 ffff8801d2eb6cd8
[   89.208136]  00000000000130c0 ffff8801d85e1fd8 ffff8801d85e0010 00000000000130c0
[   89.208149]  ffff8801d85e1fd8 00000000000130c0 ffff8801d83405c0 ffff8801d2eb6840
[   89.208162] Call Trace:
[   89.208171]  [schedule+0x3a/0x50
[   89.208181](<ffffffff81445a6a>])  [schedule_hrtimeout_range_clock+0x11d/0x140
[   89.208191](<ffffffff8144694d>])  [? xen_restore_fl_direct_reloc+0x4/0x4
[   89.208202](<ffffffff8100a05f>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.208212](<ffffffff814478b1>])  [? add_wait_queue+0x49/0x60
[   89.208222](<ffffffff8107f6d9>])  [schedule_hrtimeout_range+0xe/0x10
[   89.208231](<ffffffff8144697e>])  [poll_schedule_timeout+0x44/0x60
[   89.208240](<ffffffff8114c4e4>])  [do_select+0x56c/0x6b0
[   89.208249](<ffffffff8114d02c>])  [? get_page_from_freelist+0x1ae/0x420
[   89.208259](<ffffffff810f150e>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.208269](<ffffffff814478b1>])  [? poll_freewait+0x90/0x90
[   89.208278](<ffffffff8114c5c0>])  [? __pollwait+0xf0/0xf0
[   89.208287](<ffffffff8114c6b0>])  [? xen_force_evtchn_callback+0xd/0x10
[   89.208297](<ffffffff8100987d>])  [? check_events+0x12/0x20
[   89.208307](<ffffffff8100a072>])  [? xen_force_evtchn_callback+0xd/0x10
[   89.208316](<ffffffff8100987d>])  [? check_events+0x12/0x20
[   89.208326](<ffffffff8100a072>])  [? xen_restore_fl_direct_reloc+0x4/0x4
[   89.208335](<ffffffff8100a05f>])  [? xen_flush_tlb_single+0xce/0x1c0
[   89.208345](<ffffffff81007e2e>])  [? cpumask_any_but+0x2b/0x40
[   89.208355](<ffffffff8121e3db>])  [? flush_tlb_page+0x43/0xb0
[   89.208364](<ffffffff81041e13>])  [? xen_set_pte_at+0x3b/0x1d0
[   89.208374](<ffffffff8100965b>])  [? lru_cache_add_lru+0x28/0x50
[   89.208383](<ffffffff810f6ca8>])  [? do_wp_page+0x2f0/0x820
[   89.208392](<ffffffff8110fbc0>])  [? xen_flush_tlb+0xbe/0x1b0
[   89.208400](<ffffffff81006cfe>])  [? pte_mfn_to_pfn+0x71/0xf0
[   89.208408](<ffffffff810052f1>])  [? xen_pmd_val+0x9/0x10
[   89.208416](<ffffffff81005409>])  [? __raw_callee_save_xen_pmd_val+0x11/0x1e
[   89.208426](<ffffffff81004f19>])  [core_sys_select+0x185/0x2b0
[   89.208435](<ffffffff8114d965>])  [? handle_mm_fault+0x1c9/0x330
[   89.208444](<ffffffff81111249>])  [? do_page_fault+0x1d8/0x450
[   89.208454](<ffffffff8144b168>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.208465](<ffffffff814478b1>])  [? do_fork+0xb3/0x300
[   89.208474](<ffffffff8105d7b3>])  [sys_select+0x42/0x110
[   89.208483](<ffffffff8114dce2>])  [? audit_syscall_entry+0x1af/0x1e0
[   89.208493](<ffffffff810b52df>])  [system_call_fastpath+0x16/0x1b


[   89.222775](<ffffffff8144f752>]) block_add_chang S 0000000000000001     0  1590   1471 0x00000080
[   89.222785]  ffff8801d6efdcc8 0000000000000286 ffffffff8100a072 0000000000000000
[   89.222798]  00000000000130c0 ffff8801d6efdfd8 ffff8801d6efc010 00000000000130c0
[   89.222811]  ffff8801d6efdfd8 00000000000130c0 ffff8801d2f7a080 ffff8801d71a2080
[   89.222824] Call Trace:
[   89.222832]  [? check_events+0x12/0x20
[   89.222842](<ffffffff8100a072>])  [? xen_restore_fl_direct_reloc+0x4/0x4
[   89.222852](<ffffffff8100a05f>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.222862](<ffffffff814478b1>])  [schedule+0x3a/0x50
[   89.222872](<ffffffff81445a6a>])  [pipe_wait+0x56/0x80
[   89.222882](<ffffffff811436f6>])  [? wake_up_bit+0x40/0x40
[   89.222892](<ffffffff8107f2f0>])  [pipe_read+0x38f/0x4a0
[   89.222905](<ffffffff8114412f>])  [do_sync_read+0xda/0x120
[   89.222913](<ffffffff8113a88a>])  [? handle_mm_fault+0x1c9/0x330
[   89.222924](<ffffffff81111249>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.222935](<ffffffff814478b1>])  [? do_fork+0xb3/0x300
[   89.222945](<ffffffff8105d7b3>])  [? _raw_spin_lock_irq+0xb/0x30
[   89.222954](<ffffffff8144787b>])  [? do_sigaction+0x134/0x1d0
[   89.222965](<ffffffff8106f294>])  [vfs_read+0xc5/0x190
[   89.222976](<ffffffff8113af55>])  [sys_read+0x4c/0x90
[   89.222986](<ffffffff8113b11c>])  [system_call_fastpath+0x16/0x1b

[   89.227119](<ffffffff8144f752>]) block_add_chang R  running task        0  1914    834 0x00000080
[   89.227134]  ffff8801d5823d08 0000000000000286 ffff8801d5822000 ffffffff81447bc5
[   89.227153]  00000000000130c0 ffff8801d5823fd8 ffff8801d5822010 00000000000130c0
[   89.227172]  ffff8801d5823fd8 00000000000130c0 ffff8801d2ee83c0 ffff8801d5820340
[   89.227191] Call Trace:
[   89.227204]  [? _raw_spin_lock_irqsave+0x15/0x40
[   89.227218](<ffffffff81447bc5>])  [schedule+0x3a/0x50
[   89.227231](<ffffffff81445a6a>])  [schedule_timeout+0x167/0x2b0
[   89.227244](<ffffffff81445e47>])  [? lock_timer_base+0x70/0x70
[   89.227258](<ffffffff8106c6a0>])  [? xen_restore_fl_direct_reloc+0x4/0x4
[   89.227274](<ffffffff8100a05f>])  [audit_log_start+0x272/0x360
[   89.227287](<ffffffff810ae852>])  [? try_to_wake_up+0x2b0/0x2b0
[   89.227302](<ffffffff810532b0>])  [? do_filp_open+0x44/0xa0
[   89.227315](<ffffffff81148ce4>])  [audit_log_exit+0xba/0x950
[   89.227330](<ffffffff810b43ca>])  [audit_syscall_exit+0x254/0x260
[   89.227344](<ffffffff810b5124>])  [sysret_audit+0x16/0x20
[   89.227353](<ffffffff8144f884>]) block_add_chang W 0000000000000000     0  1919    970 0x00000080
[   89.227369]  ffff8801d7477e48 0000000000000286 0000000000000246 ffff8801d71dca58
[   89.227387]  00000000000130c0 ffff8801d7477fd8 ffff8801d7476010 00000000000130c0
[   89.227405]  ffff8801d7477fd8 00000000000130c0 ffff8801d7d18040 ffff8801d7b4a640
[   89.227423] Call Trace:
[   89.227437]  [schedule+0x3a/0x50
[   89.227449](<ffffffff81445a6a>])  [do_wait+0x203/0x270
[   89.227461](<ffffffff81062123>])  [sys_wait4+0x9e/0xf0
[   89.227474](<ffffffff8106222e>])  [? is_current_pgrp_orphaned+0xc0/0xc0
[   89.227490](<ffffffff810602c0>])  [system_call_fastpath+0x16/0x1b

And here's the Task state report from SysRq:

[   89.245902](<ffffffff8144f752>]) Sched Debug Version: v0.10, 3.2.7-6.pvops.qubes.x86_64 #1
[   89.245912] ktime                                   : 82751.255314
[   89.245920] sched_clk                               : 89245.897519
[   89.245929] cpu_clk                                 : 89245.897901
[   89.245937] jiffies                                 : 4294912984
[   89.245944] sched_clock_stable                      : 1
[   89.245951] 
[   89.245956] sysctl_sched
[   89.245964]   .sysctl_sched_latency                    : 18.000000
[   89.245972]   .sysctl_sched_min_granularity            : 2.250000
[   89.245980]   .sysctl_sched_wakeup_granularity         : 3.000000
[   89.245988]   .sysctl_sched_child_runs_first           : 0
[   89.245996]   .sysctl_sched_features                   : 24119
[   89.246004]   .sysctl_sched_tunable_scaling            : 1 (logaritmic)
[   89.246014] 
[   89.246016] cpu#0, 2591.622 MHz
[   89.246023]   .nr_running                    : 1
[   89.246031]   .load                          : 1586
[   89.246038]   .nr_switches                   : 172632
[   89.246046]   .nr_load_updates               : 4448
[   89.246053]   .nr_uninterruptible            : -56
[   89.246061]   .next_balance                  : 4294.912893
[   89.246069]   .curr->pid                     : 2036
[   89.246077]   .clock                         : 89111.955286
[   89.246085]   .cpu_load[                  : 31720
[   89.246090](0])   .cpu_load[                  : 15860
[   89.246095](1])   .cpu_load[                  : 7930
[   89.246100](2])   .cpu_load[                  : 3965
[   89.246105](3])   .cpu_load[                  : 2029
[   89.246110](4])   .yld_count                     : 3
[   89.246115]   .sched_switch                  : 0
[   89.246120]   .sched_count                   : 172745
[   89.246125]   .sched_goidle                  : 4996
[   89.246130]   .avg_idle                      : 779129
[   89.246136]   .ttwu_count                    : 168380
[   89.246141]   .ttwu_local                    : 67078
[   89.246147] 
[   89.246149] cfs_rq[  89.246154](0]:/
[)   .exec_clock                    : 64803.817319
[   89.246160]   .MIN_vruntime                  : 0.000001
[   89.246166]   .min_vruntime                  : 4673.282639
[   89.246171]   .max_vruntime                  : 0.000001
[   89.246177]   .spread                        : 0.000000
[   89.246182]   .spread0                       : 0.000000
[   89.246188]   .nr_spread_over                : 626
[   89.246193]   .nr_running                    : 1
[   89.246198]   .load                          : 1586
[   89.246203]   .load_avg                      : 0.000000
[   89.246208]   .load_period                   : 0.000000
[   89.246213]   .load_contrib                  : 0
[   89.246218]   .load_tg                       : 0
[   89.246224] 
[   89.246226] rt_rq[  89.246230](0]:/
[)   .rt_nr_running                 : 0
[   89.246235]   .rt_throttled                  : 0
[   89.246240]   .rt_time                       : 0.000000
[   89.246246]   .rt_runtime                    : 950.000000
[   89.246251] 
[   89.246253] runnable tasks:
[   89.246255]             task   PID         tree-key  switches  prio     exec-runtime         sum-exec        sum-sleep
[   89.246259] ----------------------------------------------------------------------------------------------------------
[   89.246347] R          udevd  2036      4673.282639        34   118      4673.282639       267.387580      1283.704097 /
[   89.246388] 
[   89.246390] cpu#1, 2591.622 MHz
[   89.246398]   .nr_running                    : 29
[   89.246405]   .load                          : 45894
[   89.246414]   .nr_switches                   : 176205
[   89.246421]   .nr_load_updates               : 4335
[   89.246429]   .nr_uninterruptible            : 44
[   89.246437]   .next_balance                  : 4294.912996
[   89.246444]   .curr->pid                     : 742
[   89.246453]   .clock                         : 89246.291428
[   89.246460]   .cpu_load[                  : 2048
[   89.246468](0])   .cpu_load[                  : 16783
[   89.246475](1])   .cpu_load[                  : 16330
[   89.246483](2])   .cpu_load[                  : 13906
[   89.246490](3])   .cpu_load[                  : 13259
[   89.246499](4])   .yld_count                     : 90
[   89.246506]   .sched_switch                  : 0
[   89.246513]   .sched_count                   : 176412
[   89.246520]   .sched_goidle                  : 5174
[   89.246527]   .avg_idle                      : 889484
[   89.246535]   .ttwu_count                    : 171513
[   89.246542]   .ttwu_local                    : 71430
[   89.246550] 
[   89.246552] cfs_rq[  89.246559](1]:/
[)   .exec_clock                    : 63330.262541
[   89.246578]   .MIN_vruntime                  : 5813.191013
[   89.246587]   .min_vruntime                  : 5822.191013
[   89.246595]   .max_vruntime                  : 5822.191013
[   89.246603]   .spread                        : 9.000000
[   89.246611]   .spread0                       : 1148.908374
[   89.246618]   .nr_spread_over                : 715
[   89.246626]   .nr_running                    : 26
[   89.246633]   .load                          : 38526
[   89.246640]   .load_avg                      : 0.000000
[   89.246648]   .load_period                   : 0.000000
[   89.246655]   .load_contrib                  : 0
[   89.246662]   .load_tg                       : 0
[   89.246669] 
[   89.246671] rt_rq[  89.246678](1]:/
[)   .rt_nr_running                 : 0
[   89.246685]   .rt_throttled                  : 0
[   89.246692]   .rt_time                       : 0.000000
[   89.246700]   .rt_runtime                    : 950.000000
[   89.246708] 
[   89.246710] runnable tasks:
[   89.246712]             task   PID         tree-key  switches  prio     exec-runtime         sum-exec        sum-sleep
[   89.246718] ----------------------------------------------------------------------------------------------------------
[   89.246739]  readahead-colle   730      5822.191013     11169   120      5822.191013      2038.996495      6237.015862 /
[   89.246765]          udevadm   797      5813.191013      8734   120      5813.191013      1526.317335      6527.601124 /
[   89.246812]               ls  1927      5813.191013       644   118      5813.191013       320.034303      1625.844385 /
[   89.246833]            blkid  2009      5813.191013       162   118      5813.191013      1325.987989      2197.876947 /
[   89.246851]            blkid  2013      5813.191013       120   118      5813.191013       335.243209      1098.863577 /
[   89.246868]            blkid  2019      5813.194041       137   118      5813.194041      1235.354180      1362.739400 /
[   89.246890]  block_add_chang  2063      5813.249438       138   118      5813.249438      1326.471138      1134.493612 /
[   89.246908]               ls  2067      5813.274052       126   118      5813.274052     29666.253471       847.408214 /
[   89.246925]            blkid  2075      5813.214329        98   118      5813.214329      2287.103647       258.536889 /
[   89.246943]            udevd  2083      5813.211289        32   118      5813.211289         1.132175        41.125913 /
[   89.246964] 
[   89.246965] cpu#2, 2591.622 MHz
[   89.246970]   .nr_running                    : 0
[   89.246975]   .load                          : 0
[   89.246980]   .nr_switches                   : 199282
[   89.246985]   .nr_load_updates               : 5536
[   89.246990]   .nr_uninterruptible            : -82
[   89.246996]   .next_balance                  : 4294.913012
[   89.247001]   .curr->pid                     : 0
[   89.247006]   .clock                         : 89246.796034
[   89.247012]   .cpu_load[                  : 7930
[   89.247017](0])   .cpu_load[                  : 7180
[   89.247022](1])   .cpu_load[                  : 7971
[   89.247027](2])   .cpu_load[                  : 11221
[   89.247032](3])   .cpu_load[                  : 14023
[   89.247037](4])   .yld_count                     : 0
[   89.247042]   .sched_switch                  : 0
[   89.247047]   .sched_count                   : 199587
[   89.247052]   .sched_goidle                  : 7554
[   89.247057]   .avg_idle                      : 251462
[   89.247062]   .ttwu_count                    : 181839
[   89.247067]   .ttwu_local                    : 74745
[   89.247075] 
[   89.247078] cfs_rq[  89.247085](2]:/
[)   .exec_clock                    : 69305.396961
[   89.247103]   .MIN_vruntime                  : 36016.392565
[   89.247111]   .min_vruntime                  : 36016.392565
[   89.247119]   .max_vruntime                  : 36016.392565
[   89.247127]   .spread                        : 0.000000
[   89.247135]   .spread0                       : 31343.109926
[   89.247143]   .nr_spread_over                : 768
[   89.247151]   .nr_running                    : 11
[   89.247159]   .load                          : 19032
[   89.247167]   .load_avg                      : 0.000000
[   89.247175]   .load_period                   : 0.000000
[   89.247182]   .load_contrib                  : 0
[   89.247189]   .load_tg                       : 0
[   89.247197] 
[   89.247199] rt_rq[  89.247205](2]:/
[)   .rt_nr_running                 : 0
[   89.247212]   .rt_throttled                  : 0
[   89.247219]   .rt_time                       : 0.000000
[   89.247227]   .rt_runtime                    : 950.000000
[   89.247235] 
[   89.247238] runnable tasks:
[   89.247241]             task   PID         tree-key  switches  prio     exec-runtime         sum-exec        sum-sleep
[   89.247246] ----------------------------------------------------------------------------------------------------------
[   89.247288] R          blkid  2011     36007.597351       151   118     36007.597351      1625.988098      2114.591196 /
[   89.247313]            blkid  2016     36007.716880       173   118     36007.716880      1535.689136      1660.642128 /
[   89.247336]            blkid  2017     36008.039139       152   118     36008.039139      1538.238261      1319.095550 /
[   89.247360]            blkid  2021     36008.427726       136   118     36008.427726      1266.586347      1226.972367 /
[   89.247385]            blkid  2034     36007.803898       154   118     36007.803898      1144.439495      1396.135594 /
[   89.247410] R          blkid  2046     36007.966564       120   118     36007.977135      1301.397194       742.514238 /
[   89.247435]  block_add_chang  2060     36009.970566       106   118     36009.970566       427.939440       296.273025 /
[   89.247460]               ls  2068     36008.710233       118   118     36008.710233      1446.010854      1034.858834 /
[   89.247486]            udevd  2085     36016.392565        28   118     36016.392565         0.823078        31.533285 /
[   89.247513] 
[   89.247515] cpu#3, 2591.622 MHz
[   89.247522]   .nr_running                    : 1
[   89.247529]   .load                          : 0
[   89.247536]   .nr_switches                   : 205168
[   89.247541]   .nr_load_updates               : 4375
[   89.247547]   .nr_uninterruptible            : 95
[   89.247552]   .next_balance                  : 4294.912997
[   89.247557]   .curr->pid                     : 0
[   89.247562]   .clock                         : 89247.518833
[   89.247568]   .cpu_load[                  : 7930
[   89.247572](0])   .cpu_load[                  : 6563
[   89.247577](1])   .cpu_load[                  : 9107
[   89.247583](2])   .cpu_load[                  : 12183
[   89.247587](3])   .cpu_load[                  : 14220
[   89.247593](4])   .yld_count                     : 90
[   89.247597]   .sched_switch                  : 0
[   89.247603]   .sched_count                   : 205383
[   89.247608]   .sched_goidle                  : 15370
[   89.247613]   .avg_idle                      : 276552
[   89.247618]   .ttwu_count                    : 164331
[   89.247623]   .ttwu_local                    : 66757
[   89.247628] 
[   89.247630] cfs_rq[  89.247634](3]:/
[)   .exec_clock                    : 63447.921760
[   89.247641]   .MIN_vruntime                  : 0.000001
[   89.247646]   .min_vruntime                  : 9058.756147
[   89.247652]   .max_vruntime                  : 0.000001
[   89.247657]   .spread                        : 0.000000
[   89.247662]   .spread0                       : 4385.473508
[   89.247667]   .nr_spread_over                : 792
[   89.247672]   .nr_running                    : 0
[   89.247677]   .load                          : 0
[   89.247682]   .load_avg                      : 0.000000
[   89.247688]   .load_period                   : 0.000000
[   89.247693]   .load_contrib                  : 0
[   89.247697]   .load_tg                       : 0
[   89.247702] 
[   89.247704] rt_rq[  89.247708](3]:/
[)   .rt_nr_running                 : 0
[   89.247713]   .rt_throttled                  : 0
[   89.247718]   .rt_time                       : 0.000000
[   89.247723]   .rt_runtime                    : 950.000000
[   89.247728] 
[   89.247730] runnable tasks:
[   89.247732]             task   PID         tree-key  switches  prio     exec-runtime         sum-exec        sum-sleep
[   89.247736] ---------------------------------------------------------------------------------------------------------```
Member

marmarek commented Mar 8, 2015

Comment by joanna on 30 Jul 2012 14:46 UTC
I managed to reproduce it, and was able to use SysRq this time. But first, some oopses from dmesg (there is tons of them there, just picked a few common ones):

[   89.208113] udevd           S 0000000000000000     0  1083    794 0x00000080
[   89.208123]  ffff8801d85e18d8 0000000000000282 0000000000000000 ffff8801d2eb6cd8
[   89.208136]  00000000000130c0 ffff8801d85e1fd8 ffff8801d85e0010 00000000000130c0
[   89.208149]  ffff8801d85e1fd8 00000000000130c0 ffff8801d83405c0 ffff8801d2eb6840
[   89.208162] Call Trace:
[   89.208171]  [schedule+0x3a/0x50
[   89.208181](<ffffffff81445a6a>])  [schedule_hrtimeout_range_clock+0x11d/0x140
[   89.208191](<ffffffff8144694d>])  [? xen_restore_fl_direct_reloc+0x4/0x4
[   89.208202](<ffffffff8100a05f>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.208212](<ffffffff814478b1>])  [? add_wait_queue+0x49/0x60
[   89.208222](<ffffffff8107f6d9>])  [schedule_hrtimeout_range+0xe/0x10
[   89.208231](<ffffffff8144697e>])  [poll_schedule_timeout+0x44/0x60
[   89.208240](<ffffffff8114c4e4>])  [do_select+0x56c/0x6b0
[   89.208249](<ffffffff8114d02c>])  [? get_page_from_freelist+0x1ae/0x420
[   89.208259](<ffffffff810f150e>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.208269](<ffffffff814478b1>])  [? poll_freewait+0x90/0x90
[   89.208278](<ffffffff8114c5c0>])  [? __pollwait+0xf0/0xf0
[   89.208287](<ffffffff8114c6b0>])  [? xen_force_evtchn_callback+0xd/0x10
[   89.208297](<ffffffff8100987d>])  [? check_events+0x12/0x20
[   89.208307](<ffffffff8100a072>])  [? xen_force_evtchn_callback+0xd/0x10
[   89.208316](<ffffffff8100987d>])  [? check_events+0x12/0x20
[   89.208326](<ffffffff8100a072>])  [? xen_restore_fl_direct_reloc+0x4/0x4
[   89.208335](<ffffffff8100a05f>])  [? xen_flush_tlb_single+0xce/0x1c0
[   89.208345](<ffffffff81007e2e>])  [? cpumask_any_but+0x2b/0x40
[   89.208355](<ffffffff8121e3db>])  [? flush_tlb_page+0x43/0xb0
[   89.208364](<ffffffff81041e13>])  [? xen_set_pte_at+0x3b/0x1d0
[   89.208374](<ffffffff8100965b>])  [? lru_cache_add_lru+0x28/0x50
[   89.208383](<ffffffff810f6ca8>])  [? do_wp_page+0x2f0/0x820
[   89.208392](<ffffffff8110fbc0>])  [? xen_flush_tlb+0xbe/0x1b0
[   89.208400](<ffffffff81006cfe>])  [? pte_mfn_to_pfn+0x71/0xf0
[   89.208408](<ffffffff810052f1>])  [? xen_pmd_val+0x9/0x10
[   89.208416](<ffffffff81005409>])  [? __raw_callee_save_xen_pmd_val+0x11/0x1e
[   89.208426](<ffffffff81004f19>])  [core_sys_select+0x185/0x2b0
[   89.208435](<ffffffff8114d965>])  [? handle_mm_fault+0x1c9/0x330
[   89.208444](<ffffffff81111249>])  [? do_page_fault+0x1d8/0x450
[   89.208454](<ffffffff8144b168>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.208465](<ffffffff814478b1>])  [? do_fork+0xb3/0x300
[   89.208474](<ffffffff8105d7b3>])  [sys_select+0x42/0x110
[   89.208483](<ffffffff8114dce2>])  [? audit_syscall_entry+0x1af/0x1e0
[   89.208493](<ffffffff810b52df>])  [system_call_fastpath+0x16/0x1b


[   89.222775](<ffffffff8144f752>]) block_add_chang S 0000000000000001     0  1590   1471 0x00000080
[   89.222785]  ffff8801d6efdcc8 0000000000000286 ffffffff8100a072 0000000000000000
[   89.222798]  00000000000130c0 ffff8801d6efdfd8 ffff8801d6efc010 00000000000130c0
[   89.222811]  ffff8801d6efdfd8 00000000000130c0 ffff8801d2f7a080 ffff8801d71a2080
[   89.222824] Call Trace:
[   89.222832]  [? check_events+0x12/0x20
[   89.222842](<ffffffff8100a072>])  [? xen_restore_fl_direct_reloc+0x4/0x4
[   89.222852](<ffffffff8100a05f>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.222862](<ffffffff814478b1>])  [schedule+0x3a/0x50
[   89.222872](<ffffffff81445a6a>])  [pipe_wait+0x56/0x80
[   89.222882](<ffffffff811436f6>])  [? wake_up_bit+0x40/0x40
[   89.222892](<ffffffff8107f2f0>])  [pipe_read+0x38f/0x4a0
[   89.222905](<ffffffff8114412f>])  [do_sync_read+0xda/0x120
[   89.222913](<ffffffff8113a88a>])  [? handle_mm_fault+0x1c9/0x330
[   89.222924](<ffffffff81111249>])  [? _raw_spin_unlock_irqrestore+0x11/0x20
[   89.222935](<ffffffff814478b1>])  [? do_fork+0xb3/0x300
[   89.222945](<ffffffff8105d7b3>])  [? _raw_spin_lock_irq+0xb/0x30
[   89.222954](<ffffffff8144787b>])  [? do_sigaction+0x134/0x1d0
[   89.222965](<ffffffff8106f294>])  [vfs_read+0xc5/0x190
[   89.222976](<ffffffff8113af55>])  [sys_read+0x4c/0x90
[   89.222986](<ffffffff8113b11c>])  [system_call_fastpath+0x16/0x1b

[   89.227119](<ffffffff8144f752>]) block_add_chang R  running task        0  1914    834 0x00000080
[   89.227134]  ffff8801d5823d08 0000000000000286 ffff8801d5822000 ffffffff81447bc5
[   89.227153]  00000000000130c0 ffff8801d5823fd8 ffff8801d5822010 00000000000130c0
[   89.227172]  ffff8801d5823fd8 00000000000130c0 ffff8801d2ee83c0 ffff8801d5820340
[   89.227191] Call Trace:
[   89.227204]  [? _raw_spin_lock_irqsave+0x15/0x40
[   89.227218](<ffffffff81447bc5>])  [schedule+0x3a/0x50
[   89.227231](<ffffffff81445a6a>])  [schedule_timeout+0x167/0x2b0
[   89.227244](<ffffffff81445e47>])  [? lock_timer_base+0x70/0x70
[   89.227258](<ffffffff8106c6a0>])  [? xen_restore_fl_direct_reloc+0x4/0x4
[   89.227274](<ffffffff8100a05f>])  [audit_log_start+0x272/0x360
[   89.227287](<ffffffff810ae852>])  [? try_to_wake_up+0x2b0/0x2b0
[   89.227302](<ffffffff810532b0>])  [? do_filp_open+0x44/0xa0
[   89.227315](<ffffffff81148ce4>])  [audit_log_exit+0xba/0x950
[   89.227330](<ffffffff810b43ca>])  [audit_syscall_exit+0x254/0x260
[   89.227344](<ffffffff810b5124>])  [sysret_audit+0x16/0x20
[   89.227353](<ffffffff8144f884>]) block_add_chang W 0000000000000000     0  1919    970 0x00000080
[   89.227369]  ffff8801d7477e48 0000000000000286 0000000000000246 ffff8801d71dca58
[   89.227387]  00000000000130c0 ffff8801d7477fd8 ffff8801d7476010 00000000000130c0
[   89.227405]  ffff8801d7477fd8 00000000000130c0 ffff8801d7d18040 ffff8801d7b4a640
[   89.227423] Call Trace:
[   89.227437]  [schedule+0x3a/0x50
[   89.227449](<ffffffff81445a6a>])  [do_wait+0x203/0x270
[   89.227461](<ffffffff81062123>])  [sys_wait4+0x9e/0xf0
[   89.227474](<ffffffff8106222e>])  [? is_current_pgrp_orphaned+0xc0/0xc0
[   89.227490](<ffffffff810602c0>])  [system_call_fastpath+0x16/0x1b

And here's the Task state report from SysRq:

[   89.245902](<ffffffff8144f752>]) Sched Debug Version: v0.10, 3.2.7-6.pvops.qubes.x86_64 #1
[   89.245912] ktime                                   : 82751.255314
[   89.245920] sched_clk                               : 89245.897519
[   89.245929] cpu_clk                                 : 89245.897901
[   89.245937] jiffies                                 : 4294912984
[   89.245944] sched_clock_stable                      : 1
[   89.245951] 
[   89.245956] sysctl_sched
[   89.245964]   .sysctl_sched_latency                    : 18.000000
[   89.245972]   .sysctl_sched_min_granularity            : 2.250000
[   89.245980]   .sysctl_sched_wakeup_granularity         : 3.000000
[   89.245988]   .sysctl_sched_child_runs_first           : 0
[   89.245996]   .sysctl_sched_features                   : 24119
[   89.246004]   .sysctl_sched_tunable_scaling            : 1 (logaritmic)
[   89.246014] 
[   89.246016] cpu#0, 2591.622 MHz
[   89.246023]   .nr_running                    : 1
[   89.246031]   .load                          : 1586
[   89.246038]   .nr_switches                   : 172632
[   89.246046]   .nr_load_updates               : 4448
[   89.246053]   .nr_uninterruptible            : -56
[   89.246061]   .next_balance                  : 4294.912893
[   89.246069]   .curr->pid                     : 2036
[   89.246077]   .clock                         : 89111.955286
[   89.246085]   .cpu_load[                  : 31720
[   89.246090](0])   .cpu_load[                  : 15860
[   89.246095](1])   .cpu_load[                  : 7930
[   89.246100](2])   .cpu_load[                  : 3965
[   89.246105](3])   .cpu_load[                  : 2029
[   89.246110](4])   .yld_count                     : 3
[   89.246115]   .sched_switch                  : 0
[   89.246120]   .sched_count                   : 172745
[   89.246125]   .sched_goidle                  : 4996
[   89.246130]   .avg_idle                      : 779129
[   89.246136]   .ttwu_count                    : 168380
[   89.246141]   .ttwu_local                    : 67078
[   89.246147] 
[   89.246149] cfs_rq[  89.246154](0]:/
[)   .exec_clock                    : 64803.817319
[   89.246160]   .MIN_vruntime                  : 0.000001
[   89.246166]   .min_vruntime                  : 4673.282639
[   89.246171]   .max_vruntime                  : 0.000001
[   89.246177]   .spread                        : 0.000000
[   89.246182]   .spread0                       : 0.000000
[   89.246188]   .nr_spread_over                : 626
[   89.246193]   .nr_running                    : 1
[   89.246198]   .load                          : 1586
[   89.246203]   .load_avg                      : 0.000000
[   89.246208]   .load_period                   : 0.000000
[   89.246213]   .load_contrib                  : 0
[   89.246218]   .load_tg                       : 0
[   89.246224] 
[   89.246226] rt_rq[  89.246230](0]:/
[)   .rt_nr_running                 : 0
[   89.246235]   .rt_throttled                  : 0
[   89.246240]   .rt_time                       : 0.000000
[   89.246246]   .rt_runtime                    : 950.000000
[   89.246251] 
[   89.246253] runnable tasks:
[   89.246255]             task   PID         tree-key  switches  prio     exec-runtime         sum-exec        sum-sleep
[   89.246259] ----------------------------------------------------------------------------------------------------------
[   89.246347] R          udevd  2036      4673.282639        34   118      4673.282639       267.387580      1283.704097 /
[   89.246388] 
[   89.246390] cpu#1, 2591.622 MHz
[   89.246398]   .nr_running                    : 29
[   89.246405]   .load                          : 45894
[   89.246414]   .nr_switches                   : 176205
[   89.246421]   .nr_load_updates               : 4335
[   89.246429]   .nr_uninterruptible            : 44
[   89.246437]   .next_balance                  : 4294.912996
[   89.246444]   .curr->pid                     : 742
[   89.246453]   .clock                         : 89246.291428
[   89.246460]   .cpu_load[                  : 2048
[   89.246468](0])   .cpu_load[                  : 16783
[   89.246475](1])   .cpu_load[                  : 16330
[   89.246483](2])   .cpu_load[                  : 13906
[   89.246490](3])   .cpu_load[                  : 13259
[   89.246499](4])   .yld_count                     : 90
[   89.246506]   .sched_switch                  : 0
[   89.246513]   .sched_count                   : 176412
[   89.246520]   .sched_goidle                  : 5174
[   89.246527]   .avg_idle                      : 889484
[   89.246535]   .ttwu_count                    : 171513
[   89.246542]   .ttwu_local                    : 71430
[   89.246550] 
[   89.246552] cfs_rq[  89.246559](1]:/
[)   .exec_clock                    : 63330.262541
[   89.246578]   .MIN_vruntime                  : 5813.191013
[   89.246587]   .min_vruntime                  : 5822.191013
[   89.246595]   .max_vruntime                  : 5822.191013
[   89.246603]   .spread                        : 9.000000
[   89.246611]   .spread0                       : 1148.908374
[   89.246618]   .nr_spread_over                : 715
[   89.246626]   .nr_running                    : 26
[   89.246633]   .load                          : 38526
[   89.246640]   .load_avg                      : 0.000000
[   89.246648]   .load_period                   : 0.000000
[   89.246655]   .load_contrib                  : 0
[   89.246662]   .load_tg                       : 0
[   89.246669] 
[   89.246671] rt_rq[  89.246678](1]:/
[)   .rt_nr_running                 : 0
[   89.246685]   .rt_throttled                  : 0
[   89.246692]   .rt_time                       : 0.000000
[   89.246700]   .rt_runtime                    : 950.000000
[   89.246708] 
[   89.246710] runnable tasks:
[   89.246712]             task   PID         tree-key  switches  prio     exec-runtime         sum-exec        sum-sleep
[   89.246718] ----------------------------------------------------------------------------------------------------------
[   89.246739]  readahead-colle   730      5822.191013     11169   120      5822.191013      2038.996495      6237.015862 /
[   89.246765]          udevadm   797      5813.191013      8734   120      5813.191013      1526.317335      6527.601124 /
[   89.246812]               ls  1927      5813.191013       644   118      5813.191013       320.034303      1625.844385 /
[   89.246833]            blkid  2009      5813.191013       162   118      5813.191013      1325.987989      2197.876947 /
[   89.246851]            blkid  2013      5813.191013       120   118      5813.191013       335.243209      1098.863577 /
[   89.246868]            blkid  2019      5813.194041       137   118      5813.194041      1235.354180      1362.739400 /
[   89.246890]  block_add_chang  2063      5813.249438       138   118      5813.249438      1326.471138      1134.493612 /
[   89.246908]               ls  2067      5813.274052       126   118      5813.274052     29666.253471       847.408214 /
[   89.246925]            blkid  2075      5813.214329        98   118      5813.214329      2287.103647       258.536889 /
[   89.246943]            udevd  2083      5813.211289        32   118      5813.211289         1.132175        41.125913 /
[   89.246964] 
[   89.246965] cpu#2, 2591.622 MHz
[   89.246970]   .nr_running                    : 0
[   89.246975]   .load                          : 0
[   89.246980]   .nr_switches                   : 199282
[   89.246985]   .nr_load_updates               : 5536
[   89.246990]   .nr_uninterruptible            : -82
[   89.246996]   .next_balance                  : 4294.913012
[   89.247001]   .curr->pid                     : 0
[   89.247006]   .clock                         : 89246.796034
[   89.247012]   .cpu_load[                  : 7930
[   89.247017](0])   .cpu_load[                  : 7180
[   89.247022](1])   .cpu_load[                  : 7971
[   89.247027](2])   .cpu_load[                  : 11221
[   89.247032](3])   .cpu_load[                  : 14023
[   89.247037](4])   .yld_count                     : 0
[   89.247042]   .sched_switch                  : 0
[   89.247047]   .sched_count                   : 199587
[   89.247052]   .sched_goidle                  : 7554
[   89.247057]   .avg_idle                      : 251462
[   89.247062]   .ttwu_count                    : 181839
[   89.247067]   .ttwu_local                    : 74745
[   89.247075] 
[   89.247078] cfs_rq[  89.247085](2]:/
[)   .exec_clock                    : 69305.396961
[   89.247103]   .MIN_vruntime                  : 36016.392565
[   89.247111]   .min_vruntime                  : 36016.392565
[   89.247119]   .max_vruntime                  : 36016.392565
[   89.247127]   .spread                        : 0.000000
[   89.247135]   .spread0                       : 31343.109926
[   89.247143]   .nr_spread_over                : 768
[   89.247151]   .nr_running                    : 11
[   89.247159]   .load                          : 19032
[   89.247167]   .load_avg                      : 0.000000
[   89.247175]   .load_period                   : 0.000000
[   89.247182]   .load_contrib                  : 0
[   89.247189]   .load_tg                       : 0
[   89.247197] 
[   89.247199] rt_rq[  89.247205](2]:/
[)   .rt_nr_running                 : 0
[   89.247212]   .rt_throttled                  : 0
[   89.247219]   .rt_time                       : 0.000000
[   89.247227]   .rt_runtime                    : 950.000000
[   89.247235] 
[   89.247238] runnable tasks:
[   89.247241]             task   PID         tree-key  switches  prio     exec-runtime         sum-exec        sum-sleep
[   89.247246] ----------------------------------------------------------------------------------------------------------
[   89.247288] R          blkid  2011     36007.597351       151   118     36007.597351      1625.988098      2114.591196 /
[   89.247313]            blkid  2016     36007.716880       173   118     36007.716880      1535.689136      1660.642128 /
[   89.247336]            blkid  2017     36008.039139       152   118     36008.039139      1538.238261      1319.095550 /
[   89.247360]            blkid  2021     36008.427726       136   118     36008.427726      1266.586347      1226.972367 /
[   89.247385]            blkid  2034     36007.803898       154   118     36007.803898      1144.439495      1396.135594 /
[   89.247410] R          blkid  2046     36007.966564       120   118     36007.977135      1301.397194       742.514238 /
[   89.247435]  block_add_chang  2060     36009.970566       106   118     36009.970566       427.939440       296.273025 /
[   89.247460]               ls  2068     36008.710233       118   118     36008.710233      1446.010854      1034.858834 /
[   89.247486]            udevd  2085     36016.392565        28   118     36016.392565         0.823078        31.533285 /
[   89.247513] 
[   89.247515] cpu#3, 2591.622 MHz
[   89.247522]   .nr_running                    : 1
[   89.247529]   .load                          : 0
[   89.247536]   .nr_switches                   : 205168
[   89.247541]   .nr_load_updates               : 4375
[   89.247547]   .nr_uninterruptible            : 95
[   89.247552]   .next_balance                  : 4294.912997
[   89.247557]   .curr->pid                     : 0
[   89.247562]   .clock                         : 89247.518833
[   89.247568]   .cpu_load[                  : 7930
[   89.247572](0])   .cpu_load[                  : 6563
[   89.247577](1])   .cpu_load[                  : 9107
[   89.247583](2])   .cpu_load[                  : 12183
[   89.247587](3])   .cpu_load[                  : 14220
[   89.247593](4])   .yld_count                     : 90
[   89.247597]   .sched_switch                  : 0
[   89.247603]   .sched_count                   : 205383
[   89.247608]   .sched_goidle                  : 15370
[   89.247613]   .avg_idle                      : 276552
[   89.247618]   .ttwu_count                    : 164331
[   89.247623]   .ttwu_local                    : 66757
[   89.247628] 
[   89.247630] cfs_rq[  89.247634](3]:/
[)   .exec_clock                    : 63447.921760
[   89.247641]   .MIN_vruntime                  : 0.000001
[   89.247646]   .min_vruntime                  : 9058.756147
[   89.247652]   .max_vruntime                  : 0.000001
[   89.247657]   .spread                        : 0.000000
[   89.247662]   .spread0                       : 4385.473508
[   89.247667]   .nr_spread_over                : 792
[   89.247672]   .nr_running                    : 0
[   89.247677]   .load                          : 0
[   89.247682]   .load_avg                      : 0.000000
[   89.247688]   .load_period                   : 0.000000
[   89.247693]   .load_contrib                  : 0
[   89.247697]   .load_tg                       : 0
[   89.247702] 
[   89.247704] rt_rq[  89.247708](3]:/
[)   .rt_nr_running                 : 0
[   89.247713]   .rt_throttled                  : 0
[   89.247718]   .rt_time                       : 0.000000
[   89.247723]   .rt_runtime                    : 950.000000
[   89.247728] 
[   89.247730] runnable tasks:
[   89.247732]             task   PID         tree-key  switches  prio     exec-runtime         sum-exec        sum-sleep
[   89.247736] ---------------------------------------------------------------------------------------------------------```
@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Modified by joanna on 30 Jul 2012 14:48 UTC

Member

marmarek commented Mar 8, 2015

Modified by joanna on 30 Jul 2012 14:48 UTC

@marmarek marmarek removed the worksforme label Mar 8, 2015

@marmarek marmarek reopened this Mar 8, 2015

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Comment by marmarek on 30 Jul 2012 14:51 UTC
This isn't oopses - this are task states (with call trace) :)

Member

marmarek commented Mar 8, 2015

Comment by marmarek on 30 Jul 2012 14:51 UTC
This isn't oopses - this are task states (with call trace) :)

@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Mar 8, 2015

Member

Modified by joanna on 10 Aug 2012 11:35 UTC

Member

marmarek commented Mar 8, 2015

Modified by joanna on 10 Aug 2012 11:35 UTC

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment