Re: [BUG] [BISECTED] System gets unresponsive since 2.6.35-rc1

From: Martin Kepplinger
Date: Wed Sep 15 2010 - 10:59:04 EST


Am 2010-09-15 13:14, schrieb Thomas Gleixner:
> On Wed, 15 Sep 2010, Martin Kepplinger wrote:
>
>> Hi,
>>
>> My Ubuntu 10.04, 32bit on a Lenovo G550 Laptop has the following
>> issue since .35-rc1: After a short uptime doing little things like
>> video playback, the system gets slow and stuck after some time. At
>> first, compiz-animations and everything (video playback,
>> terminal-commands) gets unusably slow. /var/log/messages comes up
>> with the following _during_ video playback. These warnings stop when
>> the video is stopped. The system stays (quite) unresponsive /
>> unusable.
>>
>> Sep 15 12:15:51 mobil pulseaudio[1456]: ratelimit.c: 19 events suppressed
>> Sep 15 12:15:57 mobil pulseaudio[1456]: ratelimit.c: 25 events suppressed
>> Sep 15 12:16:02 mobil pulseaudio[1456]: ratelimit.c: 6 events suppressed
>> Sep 15 12:16:07 mobil pulseaudio[1456]: ratelimit.c: 11 events suppressed
>> Sep 15 12:16:17 mobil pulseaudio[1456]: ratelimit.c: 12 events suppressed
>> Sep 15 12:16:23 mobil pulseaudio[1456]: ratelimit.c: 3 events suppressed
>>
>> Shutdown also hangs very soon. The problem is still present in
>> 2.6.36-rc3! I'm about to test -rc4. The last "good" one is 2.6.34.
>>
>> I bisected the problem. Unfortunately I could not revert the
>> patch. Additionally, I'm only 90% sure about the result because I
>> had to skip one step of the bisect (but since the toplevel-Makefile
>> showed "2.6.34-something", I could guess it to be "good")
>>
>> The rest of this E-Mail is the result (git show). I can only report
>> it. I'd happily test patches to it and hope this makes sense to
>> someone of you.
>
> I doubt that this is the real culprit. We just decoded a HPET problem,
> which might be the real cause. Patch is below.
>
> Can you provide the output of /proc/timer_list please ?
>
> Thanks,
>
> tglx
> ---
> commit 54ff7e595d763d894104d421b103a89f7becf47c
> Author: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
> Date: Tue Sep 14 22:10:21 2010 +0200
>
> x86: hpet: Work around hardware stupidity
>

I tested this against 2.6.35. Since I can write this after watching half an
hour of LinuxCon Videos, this fixes the problem. I hope it to get merged soon.
I'll test it against the current tree as well and will stay happy and quiet as
long as I can't find a problem.

Thanks a lot!

Martin
Timer List Version: v0.6
HRTIMER_MAX_CLOCK_BASES: 2
now at 48763215587 nsecs

cpu: 0
clock 0:
.base: c78042c4
.index: 0
.resolution: 1 nsecs
.get_time: ktime_get_real
.offset: 1284553359316792381 nsecs
active timers:
clock 1:
.base: c78042f0
.index: 1
.resolution: 1 nsecs
.get_time: ktime_get
.offset: 0 nsecs
active timers:
#0: <c7804380>, tick_sched_timer, S:01, hrtimer_start_range_ns, swapper/0
# expires at 48764000000-48764000000 nsecs [in 784413 to 784413 nsecs]
#1: <f687db64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gedit/1508
# expires at 48770791462-48770841462 nsecs [in 7575875 to 7625875 nsecs]
#2: <c2117b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, nautilus/1416
# expires at 48770851246-48770901246 nsecs [in 7635659 to 7685659 nsecs]
#3: <c1f0df40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gvfs-afc-volume/1454
# expires at 48916775057-48916825057 nsecs [in 153559470 to 153609470 nsecs]
#4: <c2217b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, empathy/1408
# expires at 49186991118-49188951116 nsecs [in 423775531 to 425735529 nsecs]
#5: <c2359acc>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, Xorg/996
# expires at 49257833999-49258333997 nsecs [in 494618412 to 495118410 nsecs]
#6: <c1fc9e9c>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, indicator-apple/1481
# expires at 49692030085-49692080085 nsecs [in 928814498 to 928864498 nsecs]
#7: <c1f53e9c>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, nautilus/1467
# expires at 50120922876-50120972876 nsecs [in 1357707289 to 1357757289 nsecs]
#8: <c1f9db64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, indicator-apple/1474
# expires at 50186662984-50189457982 nsecs [in 1423447397 to 1426242395 nsecs]
#9: <c2241b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gnome-panel/1413
# expires at 50187007949-50189971947 nsecs [in 1423792362 to 1426756360 nsecs]
#10: <c1f9bb64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, clock-applet/1473
# expires at 50187184403-50190150401 nsecs [in 1423968816 to 1426934814 nsecs]
#11: <c20efb64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, udisks-daemon/1433
# expires at 50684122950-50686110948 nsecs [in 1920907363 to 1922895361 nsecs]
#12: <c1e85b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rtkit-daemon/1406
# expires at 51892055563-51897055561 nsecs [in 3128839976 to 3133839974 nsecs]
#13: <c2243b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gnome-power-man/1414
# expires at 52186614186-52191578184 nsecs [in 3423398599 to 3428362597 nsecs]
#14: <c1df3b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gconfd-2/1376
# expires at 61187451824-61201413821 nsecs [in 12424236237 to 12438198234 nsecs]
#15: <c1dc7b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gnome-session/1335
# expires at 62187405694-62202365692 nsecs [in 13424190107 to 13439150105 nsecs]
#16: <c20edb64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, udisks-daemon/1432
# expires at 62683451247-62698908245 nsecs [in 13920235660 to 13935692658 nsecs]
#17: <c1e87f40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, sleep/1235
# expires at 83560438223-83560488223 nsecs [in 34797222636 to 34797272636 nsecs]
#18: <c1fd3b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, indicator-appli/1486
# expires at 94187527252-94234493250 nsecs [in 45424311665 to 45471277663 nsecs]
#19: <c1fd1b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gvfsd-metadata/1485
# expires at 94187214347-94246851345 nsecs [in 45423998760 to 45483635758 nsecs]
#20: <c223bf40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gdm-session-wor/1301
# expires at 330478636536-330478686536 nsecs [in 281715420949 to 281715470949 nsecs]
#21: <c20e1b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, nm-applet/1411
# expires at 332187153847-332287153847 nsecs [in 283423938260 to 283523938260 nsecs]
#22: <c1f51b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gnome-screensav/1506
# expires at 637404954416-637504954416 nsecs [in 588641738829 to 588741738829 nsecs]
.expires_next : 48764000000 nsecs
.hres_active : 1
.nr_events : 8949
.nr_retries : 1
.nr_hangs : 0
.max_hang_time : 0 nsecs
.nohz_mode : 2
.idle_tick : 48708000000 nsecs
.tick_stopped : 0
.idle_jiffies : 4294904473
.idle_calls : 18731
.idle_sleeps : 5026
.idle_entrytime : 48761860185 nsecs
.idle_waketime : 48757284701 nsecs
.idle_exittime : 48757313126 nsecs
.idle_sleeptime : 36258257723 nsecs
.iowait_sleeptime: 10879152787 nsecs
.last_jiffies : 4294904486
.next_jiffies : 4294904487
.idle_expires : 48760000000 nsecs
jiffies: 4294904486

cpu: 1
clock 0:
.base: c7a042c4
.index: 0
.resolution: 1 nsecs
.get_time: ktime_get_real
.offset: 1284553359316792381 nsecs
active timers:
clock 1:
.base: c7a042f0
.index: 1
.resolution: 1 nsecs
.get_time: ktime_get
.offset: 0 nsecs
active timers:
#0: <c7a04380>, tick_sched_timer, S:01, hrtimer_start_range_ns, swapper/0
# expires at 48765000000-48765000000 nsecs [in 1784413 to 1784413 nsecs]
#1: <f68adb64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gnome-terminal/1517
# expires at 48780988348-48781038348 nsecs [in 17772761 to 17822761 nsecs]
#2: <c2199f40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, syndaemon/1426
# expires at 48789418137-48789468137 nsecs [in 26202550 to 26252550 nsecs]
#3: <c1effb64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, indicator-sessi/1495
# expires at 48988676165-48990277163 nsecs [in 225460578 to 227061576 nsecs]
#4: <c1df7acc>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gpsd/1108
# expires at 49660673314-49661673312 nsecs [in 897457727 to 898457725 nsecs]
#5: <f68ffb64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gnome-user-shar/1542
# expires at 50187366844-50190321842 nsecs [in 1424151257 to 1427106255 nsecs]
#6: <c2283acc>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rsyslogd/774
# expires at 50857704507-50887704504 nsecs [in 2094488920 to 2124488917 nsecs]
#7: <c1e83acc>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, ssh-agent/1369
# expires at 50952443949-50962443947 nsecs [in 2189228362 to 2199228360 nsecs]
#8: <c1de1b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gnome-settings-/1383
# expires at 52185885821-52189313819 nsecs [in 3422670234 to 3426098232 nsecs]
#9: <c1df5b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, compiz/1394
# expires at 52757945535-52761945533 nsecs [in 3994729948 to 3998729946 nsecs]
#10: <c1df1acc>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, winbindd/1099
# expires at 52994025916-53024025914 nsecs [in 4230810329 to 4260810327 nsecs]
#11: <f684de9c>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gedit/1509
# expires at 55496508225-55496558225 nsecs [in 6733292638 to 6733342638 nsecs]
#12: <c1e89b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rtkit-daemon/1407
# expires at 56892083151-56892083151 nsecs [in 8128867564 to 8128867564 nsecs]
#13: <c1eafb64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, upowerd/1246
# expires at 59683477647-59695934645 nsecs [in 10920262060 to 10932719058 nsecs]
#14: <c1fcbe9c>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, indicator-apple/1490
# expires at 62890059877-62890109877 nsecs [in 14126844290 to 14126894290 nsecs]
#15: <c1efbb64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gnome-clock-app/1498
# expires at 64682362549-64699818547 nsecs [in 15919146962 to 15936602960 nsecs]
#16: <c2331f40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, cron/961
# expires at 82143942281-82143992281 nsecs [in 33380726694 to 33380776694 nsecs]
#17: <c2251e9c>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rsyslogd/786
# expires at 92488203208-92488253208 nsecs [in 43724987621 to 43725037621 nsecs]
#18: <c22b3b64>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, polipo/967
# expires at 1521115124444-1521215124444 nsecs [in 1472351908857 to 1472451908857 nsecs]
#19: <c1d19f40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, atd/962
# expires at 3621115433141-3621115483141 nsecs [in 3572352217554 to 3572352267554 nsecs]
.expires_next : 48765000000 nsecs
.hres_active : 1
.nr_events : 8218
.nr_retries : 1
.nr_hangs : 0
.max_hang_time : 0 nsecs
.nohz_mode : 2
.idle_tick : 48709000000 nsecs
.tick_stopped : 0
.idle_jiffies : 4294904473
.idle_calls : 16954
.idle_sleeps : 3813
.idle_entrytime : 48761516638 nsecs
.idle_waketime : 48756053407 nsecs
.idle_exittime : 48757476973 nsecs
.idle_sleeptime : 37238099743 nsecs
.iowait_sleeptime: 7873142111 nsecs
.last_jiffies : 4294904486
.next_jiffies : 4294904487
.idle_expires : 48756000000 nsecs
jiffies: 4294904486


Tick Device: mode: 1
Broadcast device
Clock Event Device: hpet
max_delta_ns: 149983005959
min_delta_ns: 5000
mult: 61496114
shift: 32
mode: 3
next_event: 48764000000 nsecs
set_next_event: hpet_legacy_next_event
set_mode: hpet_legacy_set_mode
event_handler: tick_handle_oneshot_broadcast
retries: 1706
tick_broadcast_mask: 00000003
tick_broadcast_oneshot_mask: 00000001


Tick Device: mode: 1
Per CPU device: 0
Clock Event Device: lapic
max_delta_ns: 672747792
min_delta_ns: 1202
mult: 53554680
shift: 32
mode: 1
next_event: 48764000000 nsecs
set_next_event: lapic_next_event
set_mode: lapic_timer_setup
event_handler: hrtimer_interrupt
retries: 1917

Tick Device: mode: 1
Per CPU device: 1
Clock Event Device: lapic
max_delta_ns: 672747792
min_delta_ns: 1202
mult: 53554680
shift: 32
mode: 3
next_event: 48765000000 nsecs
set_next_event: lapic_next_event
set_mode: lapic_timer_setup
event_handler: hrtimer_interrupt
retries: 1780