[Bug 53216] Re: BUG() report in getnstimeofday: soft lockup

[Jerome Lacoste]

On 10/11/06, Hervé Fache <herve at lucidia.net> wrote:
>
> gst: as you are running a vanilla kernel (or almost), and assuming it
> is not tainted, maybe you could report the problem on the lkml?
>
> They will be a pain because Skype is proprietory, but the bug is
> clearly a kernel bug, and other applications could potentially trigger
> it.
>
> As you said, it's a DoS vulnerability.


I've got some more information. I just restarted skype an hour ago and
managed to get a small slow down. Not long enough to trigger the soft lockup
but long enough to block my machine several seconds.

I had started skype using strace -tt -T

Problem happend at 15h4x local time, so

jerome at dolcevita:~$ grep "^15:4" /tmp/skype.log.failure | grep -v "\<0\."
15:44:43.941237 sched_setscheduler(21260, SCHED_FIFO, { 99 }) = 0 <3.200750>
15:44:47.164665 sched_setscheduler(21263, SCHED_FIFO, { 99 }) = 0 <7.981930>
15:45:34.548964 select(40, [3 4 5 7 39], [], [], {0, 496177}

so sched_setscheduler appears to be the handing call. It's not something
that is called often.

> grep sched_setscheduler /tmp/skype.log.failure
14:15:47.636727 sched_setscheduler(7353, SCHED_FIFO, { 99 }) = 0 <0.000040>
14:15:47.637092 sched_setscheduler(7354, SCHED_FIFO, { 99 }) = 0 <0.000022>
14:15:47.637453 sched_setscheduler(7355, SCHED_FIFO, { 99 }) = 0 <0.000022>
14:15:47.637805 sched_setscheduler(7356, SCHED_FIFO, { 99 }) = 0 <0.000021>
14:15:47.638156 sched_setscheduler(7357, SCHED_FIFO, { 2 }) = 0 <0.000022>
14:37:06.699271 sched_setscheduler(10419, SCHED_FIFO, { 99 }) = 0 <0.000036>
14:37:06.699499 sched_setscheduler(10420, SCHED_FIFO, { 99 }) = 0 <1.003012>
14:37:07.702810 sched_setscheduler(10421, SCHED_FIFO, { 99 }) = 0 <0.000028>
14:37:07.703027 sched_setscheduler(10422, SCHED_FIFO, { 99 }) = 0 <2.511436>
14:37:10.215049 sched_setscheduler(10423, SCHED_FIFO, { 2 }) = 0 <0.000027>
15:44:43.941004 sched_setscheduler(21259, SCHED_FIFO, { 99 }) = 0 <0.000038>
15:44:43.941237 sched_setscheduler(21260, SCHED_FIFO, { 99 }) = 0 <3.200750>
15:44:47.164437 sched_setscheduler(21262, SCHED_FIFO, { 99 }) = 0 <0.000030>
15:44:47.164665 sched_setscheduler(21263, SCHED_FIFO, { 99 }) = 0 <7.981930>
15:44:55.147148 sched_setscheduler(21264, SCHED_FIFO, { 2 }) = 0 <0.000027>

Here's the problematic strace log extract:


15:44:43.940671 ioctl(40, USBDEVFS_IOCTL, 0xbf9d95c0) = 0 <0.000011>
15:44:43.940733 ioctl(40, USBDEVFS_DISCONNECT, 0xbf9d9d04) = 0 <0.000010>
15:44:43.940825 clone(child_stack=0xb62df4c4,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|CLONE_DETACHED,
parent_tidptr=0xb62dfbf8, {entry_number:6, base_addr:0xb62dfbb0,
limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1,
seg_not_present:0, useable:1}, child_tidptr=0xb62dfbf8) = 21259 <0.000022>
15:44:43.940944 sched_get_priority_max(SCHED_FIFO) = 99 <0.000010>
15:44:43.941004 sched_setscheduler(21259, SCHED_FIFO, { 99 }) = 0 <0.000038>
15:44:43.941101 clone(child_stack=0xb52dd4c4,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|CLONE_DETACHED,
parent_tidptr=0xb52ddbf8, {entry_number:6, base_addr:0xb52ddbb0,
limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1,
seg_not_present:0, useable:1}, child_tidptr=0xb52ddbf8) = 21260 <0.000016>
15:44:43.941179 sched_get_priority_max(SCHED_FIFO) = 99 <0.000009>
15:44:43.941237 sched_setscheduler(21260, SCHED_FIFO, { 99 }) = 0 <3.200750>
15:44:47.164163 clone(child_stack=0xb6ae04c4,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|CLONE_DETACHED,
parent_tidptr=0xb6ae0bf8, {entry_number:6, base_addr:0xb6ae0bb0,
limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1,
seg_not_present:0, useable:1}, child_tidptr=0xb6ae0bf8) = 21262 <0.000036>
15:44:47.164377 sched_get_priority_max(SCHED_FIFO) = 99 <0.000009>
15:44:47.164437 sched_setscheduler(21262, SCHED_FIFO, { 99 }) = 0 <0.000030>
15:44:47.164533 clone(child_stack=0xb4adc4c4,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|CLONE_DETACHED,
parent_tidptr=0xb4adcbf8, {entry_number:6, base_addr:0xb4adcbb0,
limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1,
seg_not_present:0, useable:1}, child_tidptr=0xb4adcbf8) = 21263 <0.000016>
15:44:47.164609 sched_get_priority_max(SCHED_FIFO) = 99 <0.000008>
15:44:47.164665 sched_setscheduler(21263, SCHED_FIFO, { 99 }) = 0 <7.981930>
15:44:55.146712 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb3adb000 <0.000022>
15:44:55.146892 mprotect(0xb3adb000, 4096, PROT_NONE) = 0 <0.000012>
15:44:55.146961 clone(child_stack=0xb42db4c4,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|CLONE_DETACHED,
parent_tidptr=0xb42dbbf8, {entry_number:6, base_addr:0xb42dbbb0,
limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1,
seg_not_present:0, useable:1}, child_tidptr=0xb42dbbf8) = 21264 <0.000062>
15:44:55.147090 sched_get_priority_min(SCHED_FIFO) = 1 <0.000008>
15:44:55.147148 sched_setscheduler(21264, SCHED_FIFO, { 2 }) = 0 <0.000027>

I keep the 180 M strace log in case anyone wants it... This should be fed to
skype developpers and lkml.

Jerome

-- 
BUG() report in getnstimeofday: soft lockup
https://launchpad.net/bugs/53216