Re: ftrace: ftrace_bug, ftrace failed to modify nva3_ram_init

[Sasha Levin <sasha.levin@oracle.com>]

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

On 04/08/2014 11:23 AM, Steven Rostedt wrote:
> On Tue, 08 Apr 2014 11:02:07 -0400
> Sasha Levin <sasha.levin@oracle.com> wrote:
> 
>> On 04/08/2014 10:59 AM, Steven Rostedt wrote:
>>> On Tue, 08 Apr 2014 10:26:56 -0400
>>> Sasha Levin <sasha.levin@oracle.com> wrote:
>>>
>>>> Hi all,
>>>>
>>>> While fuzzing with trinity inside a KVM tools guest running the latest -next
>>>> kernel, I've stumbled on the following:
>>>>
>>>> [ 2983.109380] WARNING: CPU: 0 PID: 744 at kernel/trace/ftrace.c:1704 ftrace_bug+0xb0/0x280()
>>>> [ 2983.110893] Modules linked in:
>>>> [ 2983.111439] CPU: 0 PID: 744 Comm: trinity-main Tainted: G        W     3.14.0-next-20140407-sasha-00023-gd35b0d6 #382
>>>
>>> What was the warning before this?
>>
>> There was nothing before that in both cases I've seen this issue.
> 
> I believe the "W" taint means there was a previous warning.

Well, there were, but they're irrelevant. For me some happen on boot
because I try to test odd drivers:

[   15.555681] WARNING: CPU: 21 PID: 1 at arch/x86/mm/ioremap.c:102 __ioremap_caller+0x
19e/0x3b0()
[   15.556489] Modules linked in:
[   15.556804] CPU: 21 PID: 1 Comm: swapper/0 Not tainted 3.14.0-next-20140407-sasha-00
023-gd35b0d6 #382
[   15.557686]  0000000000000009 ffff880030203ca8 ffffffff9f52ee51 0000000000000000
[   15.558450]  0000000000000000 ffff880030203ce8 ffffffff9c15a2dc ffff880030203cd8
[   15.559203]  ffffea0000800000 00000000000201ff 0000000020000000 0000000000020000
[   15.559964] Call Trace:
[   15.560328]  [<ffffffff9f52ee51>] dump_stack+0x4f/0x7c
[   15.560838]  [<ffffffff9c15a2dc>] warn_slowpath_common+0x8c/0xc0
[   15.561463]  [<ffffffff9c15a32a>] warn_slowpath_null+0x1a/0x20
[   15.562013]  [<ffffffff9c0c00ce>] __ioremap_caller+0x19e/0x3b0
[   15.562573]  [<ffffffffa234870e>] ? nettel_init+0x9a/0x4d8
[   15.563099]  [<ffffffff9c0c0337>] ioremap_nocache+0x17/0x20
[   15.563653]  [<ffffffffa234870e>] nettel_init+0x9a/0x4d8
[   15.564296]  [<ffffffff9cb067fb>] ? kobject_uevent+0xb/0x10
[   15.564838]  [<ffffffff9d0d1cbb>] ? driver_register+0xcb/0xe0
[   15.565400]  [<ffffffffa2348659>] ? init_netsc520+0x102/0x102
[   15.565949]  [<ffffffffa2348674>] ? mtd_pci_driver_init+0x1b/0x1b
[   15.566519]  [<ffffffff9c00216a>] do_one_initcall+0xca/0x1d0
[   15.567026]  [<ffffffff9c184e00>] ? parse_args+0x270/0x460
[   15.567554]  [<ffffffffa22bc128>] kernel_init_freeable+0x1d5/0x26c
[   15.568145]  [<ffffffffa22bb848>] ? loglevel+0x31/0x31
[   15.568648]  [<ffffffff9f512360>] ? rest_init+0x140/0x140
[   15.569170]  [<ffffffff9f51236e>] kernel_init+0xe/0x100
[   15.569685]  [<ffffffff9f5854bc>] ret_from_fork+0x7c/0xb0
[   15.570327]  [<ffffffff9f512360>] ? rest_init+0x140/0x140

I've attached the entire log from that run just to clear that up.

>>>> [ 2983.112845]  0000000000000009 ffff88002c4e3b88 ffffffffa252ee51 0000000000002420
>>>> [ 2983.113993]  0000000000000000 ffff88002c4e3bc8 ffffffff9f15a2dc ffffffff9fffffc0
>>>> [ 2983.115134]  ffff88018aaad530 ffffffffa0000000 000000000000ad53 ffffffffa6486e10
>>>> [ 2983.116221] Call Trace:
>>>> [ 2983.116603] dump_stack (lib/dump_stack.c:52)
>>>> [ 2983.117306] warn_slowpath_common (kernel/panic.c:419)
>>>> [ 2983.118252] ? nva3_ram_prog (drivers/gpu/drm/nouveau/core/subdev/fb/ramnva3.c:318)
>>>> [ 2983.119091] ? nva3_ram_tidy (drivers/gpu/drm/nouveau/core/subdev/fb/ramnva3.c:326)
>>>> [ 2983.119836] ? __fentry__ (arch/x86/kernel/entry_64.S:106)
>>>> [ 2983.121379] warn_slowpath_null (kernel/panic.c:454)
>>>> [ 2983.122635] ftrace_bug (kernel/trace/ftrace.c:1704 (discriminator 3))
>>>> [ 2983.123688] ftrace_replace_code (arch/x86/kernel/ftrace.c:625 (discriminator 3))
>>>> [ 2983.124938] ftrace_modify_all_code (kernel/trace/ftrace.c:2011)
>>>> [ 2983.126208] arch_ftrace_update_code (arch/x86/include/asm/atomic.h:103 arch/x86/kernel/ftrace.c:680)
>>>> [ 2983.127613] ftrace_run_update_code (kernel/trace/ftrace.c:2088)
>>>> [ 2983.128540] ftrace_startup_enable (kernel/trace/ftrace.c:2114)
>>>> [ 2983.129392] ftrace_startup (kernel/trace/ftrace.c:2146)
>>>> [ 2983.130679] register_ftrace_function (kernel/trace/ftrace.c:4864)
>>>> [ 2983.131667] perf_ftrace_event_register (kernel/trace/trace_event_perf.c:356)
>>>> [ 2983.132590] perf_trace_init (kernel/trace/trace_event_perf.c:187 kernel/trace/trace_event_perf.c:206)
>>>> [ 2983.133377] ? __lock_is_held (kernel/locking/lockdep.c:3516)
>>>> [ 2983.134181] perf_tp_event_init (kernel/events/core.c:5937)
>>>> [ 2983.135043] perf_init_event (kernel/events/core.c:6598)
>>>> [ 2983.135882] ? perf_pmu_unregister (kernel/events/core.c:6577)
>>>> [ 2983.136803] perf_event_alloc (kernel/events/core.c:6754)
>>>> [ 2983.137831] SYSC_perf_event_open (kernel/events/core.c:7062)
>>>> [ 2983.138798] ? preempt_count_sub (kernel/sched/core.c:2526)
>>>> [ 2983.139643] ? context_tracking_user_exit (arch/x86/include/asm/paravirt.h:809 (discriminator 2) kernel/context_tracking.c:182 (discriminator 2))
>>>> [ 2983.140912] ? context_tracking_user_exit (arch/x86/include/asm/paravirt.h:809 (discriminator 2) kernel/context_tracking.c:182 (discriminator 2))
>>>> [ 2983.141941] SyS_perf_event_open (kernel/events/core.c:6990)
>>>> [ 2983.142771] tracesys (arch/x86/kernel/entry_64.S:749)
>>>> [ 2983.144740] ---[ end trace 6321065f5978f85b ]---
>>>> [ 2983.145355] ftrace failed to modify nva3_ram_init (drivers/gpu/drm/nouveau/core/subdev/fb/ramnva3.c:326)
>>>> [ 2983.146357]  actual: 90:66:66:66:90
>>>
>>> Hmm, I wonder what the "ideal" nop is on this machine. But I think it
>>> should probably have been 66:66:66:66:90?
>>>
>>> Is this reproducible?
>>
>> It happened twice during the overnight fuzzing session, so while I can't
>> force it to happen again I'm assuming that it'll show up again if we
>> wait enough.
> 
> Is it always the same function that fails? (I would highly doubt it
> would be). Also, do you have any idea of what the sequence of events
> that were performed was?

It was exactly the same function and trace in both cases.

Unfortunately I don't have a trace since it seems that trying to log
anything in userspace makes fuzzing slow and pointless.

However, I'd be happy to add any patch that might help figure this out
into the kernel code.


Thanks,
Sasha

[-- Attachment #2: 1.2.txt.gz --]
[-- Type: application/gzip, Size: 200053 bytes --]