2.6.25-rc8-mm2 - ftraced chews 100% of a CPU

Valdis.Kletnieks
2008-04-12T10:48:01Z

[-- Attachment #1: Type: text/plain, Size: 3174 bytes --]

On Thu, 10 Apr 2008 20:33:54 PDT, Andrew Morton said:
> ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.25-rc8/2.6.25-rc8-mm2/

(Man, everything I look at tonight falls over.. I'm jinxed :)

So I built a kernel with:

% zgrep FTRACE /proc/config.gz
CONFIG_HAVE_FTRACE=y
CONFIG_FTRACE=y
CONFIG_DYNAMIC_FTRACE=y
CONFIG_FTRACE_SELFTEST=y
CONFIG_FTRACE_STARTUP_TEST=y

It ran pretty much OK for about 12 minutes, and then gkrellm reported tons of
system time, and 'top' confirms it:

top - 06:27:28 up 25 min, 3 users, load average: 1.21, 1.20, 1.02
Tasks: 132 total, 3 running, 128 sleeping, 0 stopped, 1 zombie
Cpu(s): 0.7%us, 50.7%sy, 0.0%ni, 48.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 2054764k total, 773648k used, 1281116k free, 32008k buffers
Swap: 2031608k total, 0k used, 2031608k free, 425696k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17 root 15 -5 0 0 0 R 99.8 0.0 13:04.53 ftraced
2717 root 20 0 169m 60m 11m S 2.0 3.0 1:14.71 X

And the CPUs are sitting at around 58C, which is their usual temp when
running flat-out, so there's actual looping happening.

I see this in the dmesg from right around when it went belly-up:

[ 725.345544] hm, dftrace overflow: 127 changes (0 total) in 273 usecs
[ 725.345562] ------------[ cut here ]------------
[ 725.345568] WARNING: at kernel/trace/ftrace.c:658 ftraced+0x138/0x1f0()

(no I have no idea what the system was doing at that instant)

and 'echo t > /proc/sysrq-trigger' tells us:

[ 2368.256762] ftraced R running task 5952 17 2
[ 2368.256769] ffff81000101b940 000000010101f800 ffff81007f957d10 ffffffff802302c9
[ 2368.256777] ffff81007f954480 0000000000000000 00000000ab636be3 ffffffff805e35ec
[ 2368.256784] ffff81007f957d50 ffffffff80213b72 0000000000000246 ffffffff8022ea19
[ 2368.256791] Call Trace:
[ 2368.256796] [<ffffffff805e0632>] ? schedule+0x3e/0x6a9
[ 2368.256801] [<ffffffff80230be3>] ? pick_next_task_fair+0xa0/0xc2
[ 2368.256806] [<ffffffff8028d690>] ? trace_preempt_on+0x1c/0x32
[ 2368.256811] [<ffffffff805e6469>] ? sub_preempt_count+0x49/0x73
[ 2368.256817] [<ffffffff805e35ec>] ? _spin_lock_irqsave+0x35/0x69
[ 2368.256826] [<ffffffff8024afed>] ? __mod_timer+0xce/0xf4
[ 2368.256830] [<ffffffff8024ad0a>] ? del_timer_sync+0x28/0x4d
[ 2368.256836] [<ffffffff805e1152>] ? schedule_timeout+0xac/0xdc
[ 2368.256840] [<ffffffff8024a74b>] ? process_timeout+0x0/0x37
[ 2368.256844] [<ffffffff8024af4f>] ? __mod_timer+0x30/0xf4
[ 2368.256851] [<ffffffff80286ef0>] ? ftraced+0x52/0x1f0
[ 2368.256855] [<ffffffff80257bbf>] ? kthread+0x0/0xa4
[ 2368.256859] [<ffffffff80286e9e>] ? ftraced+0x0/0x1f0
[ 2368.256863] [<ffffffff80257c20>] ? kthread+0x61/0xa4
[ 2368.256868] [<ffffffff8020d7f8>] ? child_rip+0xa/0x12
[ 2368.256873] [<ffffffff8020cee0>] ? restore_args+0x0/0x30
[ 2368.256878] [<ffffffff80257bbf>] ? kthread+0x0/0xa4
[ 2368.256882] [<ffffffff8020d7ee>] ? child_rip+0x0/0x12

Hopefully this tells you something?

[-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --]