1. 19 Sep, 2019 2 commits
  2. 17 Sep, 2019 5 commits
    • Steven Rostedt (VMware)'s avatar
      selftests/ftrace: Select an existing function in kprobe_eventname test · 604e3548
      Steven Rostedt (VMware) authored
      Running the ftrace selftests on the latest kernel caused the
      kprobe_eventname test to fail. It was due to the test that searches for
      a function with at "dot" in the name and adding a probe to that.
      Unfortunately, for this test, it picked:
      
       optimize_nops.isra.2.cold.4
      
      Which happens to be marked as "__init", which means it no longer exists
      in the kernel! (kallsyms keeps those function names around for tracing
      purposes)
      
      As only functions that still exist are in the
      available_filter_functions file, as they are removed when the functions
      are freed at boot or module exit, have the test search for a function
      with ".isra." in the name as well as being in the
      available_filter_functions (if the file exists).
      
      Link: http://lkml.kernel.org/r/20190322150923.1b58eca5@gandalf.local.homeAcked-by: default avatarMasami Hiramatsu <mhiramat@kernel.org>
      Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      604e3548
    • Masami Hiramatsu's avatar
      tracing/kprobe: Fix NULL pointer access in trace_porbe_unlink() · d59fae6f
      Masami Hiramatsu authored
      Fix NULL pointer access in trace_probe_unlink() by initializing
      trace_probe.list correctly in trace_probe_init().
      
      In the error case of trace_probe_init(), it can call trace_probe_unlink()
      before initializing trace_probe.list member. This causes NULL pointer
      dereference at list_del_init() in trace_probe_unlink().
      
      Syzbot reported :
      
      kasan: CONFIG_KASAN_INLINE enabled
      kasan: GPF could be caused by NULL-ptr deref or user memory access
      general protection fault: 0000 [#1] PREEMPT SMP KASAN
      CPU: 1 PID: 8633 Comm: syz-executor797 Not tainted 5.3.0-rc8-next-20190915
      #0
      Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
      Google 01/01/2011
      RIP: 0010:__list_del_entry_valid+0x85/0xf5 lib/list_debug.c:51
      Code: 0f 84 e1 00 00 00 48 b8 22 01 00 00 00 00 ad de 49 39 c4 0f 84 e2 00
      00 00 48 b8 00 00 00 00 00 fc ff df 4c 89 e2 48 c1 ea 03 <80> 3c 02 00 75
      53 49 8b 14 24 4c 39 f2 0f 85 99 00 00 00 49 8d 7d
      RSP: 0018:ffff888090a7f9d8 EFLAGS: 00010246
      RAX: dffffc0000000000 RBX: ffff88809b6f90c0 RCX: ffffffff817c0ca9
      RDX: 0000000000000000 RSI: ffffffff817c0a73 RDI: ffff88809b6f90c8
      RBP: ffff888090a7f9f0 R08: ffff88809a04e600 R09: ffffed1015d26aed
      R10: ffffed1015d26aec R11: ffff8880ae935763 R12: 0000000000000000
      R13: 0000000000000000 R14: ffff88809b6f90c0 R15: ffff88809b6f90d0
      FS:  0000555556f99880(0000) GS:ffff8880ae900000(0000) knlGS:0000000000000000
      CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
      CR2: 00000000006cc090 CR3: 00000000962b2000 CR4: 00000000001406e0
      DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
      DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
      Call Trace:
        __list_del_entry include/linux/list.h:131 [inline]
        list_del_init include/linux/list.h:190 [inline]
        trace_probe_unlink+0x1f/0x200 kernel/trace/trace_probe.c:959
        trace_probe_cleanup+0xd3/0x110 kernel/trace/trace_probe.c:973
        trace_probe_init+0x3f2/0x510 kernel/trace/trace_probe.c:1011
        alloc_trace_uprobe+0x5e/0x250 kernel/trace/trace_uprobe.c:353
        create_local_trace_uprobe+0x109/0x4a0 kernel/trace/trace_uprobe.c:1508
        perf_uprobe_init+0x131/0x210 kernel/trace/trace_event_perf.c:314
        perf_uprobe_event_init+0x106/0x1a0 kernel/events/core.c:8898
        perf_try_init_event+0x135/0x590 kernel/events/core.c:10184
        perf_init_event kernel/events/core.c:10228 [inline]
        perf_event_alloc.part.0+0x1b89/0x33d0 kernel/events/core.c:10505
        perf_event_alloc kernel/events/core.c:10887 [inline]
        __do_sys_perf_event_open+0xa2d/0x2d00 kernel/events/core.c:10989
        __se_sys_perf_event_open kernel/events/core.c:10871 [inline]
        __x64_sys_perf_event_open+0xbe/0x150 kernel/events/core.c:10871
        do_syscall_64+0xfa/0x760 arch/x86/entry/common.c:290
        entry_SYSCALL_64_after_hwframe+0x49/0xbe
      
      Link: http://lkml.kernel.org/r/156869709721.22406.5153754822203046939.stgit@devnote2
      
      Reported-by: syzbot+2f807f4d3a2a4e87f18f@syzkaller.appspotmail.com
      Fixes: ca89bc07 ("tracing/kprobe: Add multi-probe per event support")
      Signed-off-by: default avatarMasami Hiramatsu <mhiramat@kernel.org>
      Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      d59fae6f
    • Tom Zanussi's avatar
      tracing: Make sure variable reference alias has correct var_ref_idx · 17f8607a
      Tom Zanussi authored
      Original changelog from Steve Rostedt (except last sentence which
      explains the problem, and the Fixes: tag):
      
      I performed a three way histogram with the following commands:
      
      echo 'irq_lat u64 lat pid_t pid' > synthetic_events
      echo 'wake_lat u64 lat u64 irqlat pid_t pid' >> synthetic_events
      echo 'hist:keys=common_pid:irqts=common_timestamp.usecs if function == 0xffffffff81200580' > events/timer/hrtimer_start/trigger
      echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$irqts:onmatch(timer.hrtimer_start).irq_lat($lat,pid) if common_flags & 1' > events/sched/sched_waking/trigger
      echo 'hist:keys=pid:wakets=common_timestamp.usecs,irqlat=lat' > events/synthetic/irq_lat/trigger
      echo 'hist:keys=next_pid:lat=common_timestamp.usecs-$wakets,irqlat=$irqlat:onmatch(synthetic.irq_lat).wake_lat($lat,$irqlat,next_pid)' > events/sched/sched_switch/trigger
      echo 1 > events/synthetic/wake_lat/enable
      
      Basically I wanted to see:
      
       hrtimer_start (calling function tick_sched_timer)
      
      Note:
      
        # grep tick_sched_timer /proc/kallsyms
      ffffffff81200580 t tick_sched_timer
      
      And save the time of that, and then record sched_waking if it is called
      in interrupt context and with the same pid as the hrtimer_start, it
      will record the latency between that and the waking event.
      
      I then look at when the task that is woken is scheduled in, and record
      the latency between the wakeup and the task running.
      
      At the end, the wake_lat synthetic event will show the wakeup to
      scheduled latency, as well as the irq latency in from hritmer_start to
      the wakeup. The problem is that I found this:
      
                <idle>-0     [007] d...   190.485261: wake_lat: lat=27 irqlat=190485230 pid=698
                <idle>-0     [005] d...   190.485283: wake_lat: lat=40 irqlat=190485239 pid=10
                <idle>-0     [002] d...   190.488327: wake_lat: lat=56 irqlat=190488266 pid=335
                <idle>-0     [005] d...   190.489330: wake_lat: lat=64 irqlat=190489262 pid=10
                <idle>-0     [003] d...   190.490312: wake_lat: lat=43 irqlat=190490265 pid=77
                <idle>-0     [005] d...   190.493322: wake_lat: lat=54 irqlat=190493262 pid=10
                <idle>-0     [005] d...   190.497305: wake_lat: lat=35 irqlat=190497267 pid=10
                <idle>-0     [005] d...   190.501319: wake_lat: lat=50 irqlat=190501264 pid=10
      
      The irqlat seemed quite large! Investigating this further, if I had
      enabled the irq_lat synthetic event, I noticed this:
      
                <idle>-0     [002] d.s.   249.429308: irq_lat: lat=164968 pid=335
                <idle>-0     [002] d...   249.429369: wake_lat: lat=55 irqlat=249429308 pid=335
      
      Notice that the timestamp of the irq_lat "249.429308" is awfully
      similar to the reported irqlat variable. In fact, all instances were
      like this. It appeared that:
      
        irqlat=$irqlat
      
      Wasn't assigning the old $irqlat to the new irqlat variable, but
      instead was assigning the $irqts to it.
      
      The issue is that assigning the old $irqlat to the new irqlat variable
      creates a variable reference alias, but the alias creation code
      forgets to make sure the alias uses the same var_ref_idx to access the
      reference.
      
      Link: http://lkml.kernel.org/r/1567375321.5282.12.camel@kernel.org
      
      Cc: Linux Trace Devel <linux-trace-devel@vger.kernel.org>
      Cc: linux-rt-users <linux-rt-users@vger.kernel.org>
      Cc: stable@vger.kernel.org
      Fixes: 7e8b88a3 ("tracing: Add hist trigger support for variable reference aliases")
      Reported-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      Signed-off-by: default avatarTom Zanussi <zanussi@kernel.org>
      Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      17f8607a
    • Andy Shevchenko's avatar
      tracing: Be more clever when dumping hex in __print_hex() · 119cdbdb
      Andy Shevchenko authored
      Hex dump as many as 16 bytes at once in trace_print_hex_seq()
      instead of byte-by-byte approach.
      
      Link: http://lkml.kernel.org/r/20190806151543.86061-1-andriy.shevchenko@linux.intel.comSigned-off-by: default avatarAndy Shevchenko <andriy.shevchenko@linux.intel.com>
      Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      119cdbdb
    • Changbin Du's avatar
      ftrace: Simplify ftrace hash lookup code in clear_func_from_hash() · 08468754
      Changbin Du authored
      Function ftrace_lookup_ip() will check empty hash table. So we don't
      need extra check outside.
      
      Link: http://lkml.kernel.org/r/20190910143336.13472-1-changbin.du@gmail.comSigned-off-by: default avatarChangbin Du <changbin.du@gmail.com>
      Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      08468754
  3. 05 Sep, 2019 1 commit
  4. 31 Aug, 2019 28 commits
  5. 30 Aug, 2019 3 commits
    • Naveen N. Rao's avatar
      ftrace: Check for successful allocation of hash · 5b0022dd
      Naveen N. Rao authored
      In register_ftrace_function_probe(), we are not checking the return
      value of alloc_and_copy_ftrace_hash(). The subsequent call to
      ftrace_match_records() may end up dereferencing the same. Add a check to
      ensure this doesn't happen.
      
      Link: http://lkml.kernel.org/r/26e92574f25ad23e7cafa3cf5f7a819de1832cbe.1562249521.git.naveen.n.rao@linux.vnet.ibm.com
      
      Cc: stable@vger.kernel.org
      Fixes: 1ec3a81a ("ftrace: Have each function probe use its own ftrace_ops")
      Signed-off-by: default avatarNaveen N. Rao <naveen.n.rao@linux.vnet.ibm.com>
      Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      5b0022dd
    • Steven Rostedt (VMware)'s avatar
      ftrace: Check for empty hash and comment the race with registering probes · 372e0d01
      Steven Rostedt (VMware) authored
      The race between adding a function probe and reading the probes that exist
      is very subtle. It needs a comment. Also, the issue can also happen if the
      probe has has the EMPTY_HASH as its func_hash.
      
      Cc: stable@vger.kernel.org
      Fixes: 7b60f3d8 ("ftrace: Dynamically create the probe ftrace_ops for the trace_array")
      Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      372e0d01
    • Naveen N. Rao's avatar
      ftrace: Fix NULL pointer dereference in t_probe_next() · 7bd46644
      Naveen N. Rao authored
      LTP testsuite on powerpc results in the below crash:
      
        Unable to handle kernel paging request for data at address 0x00000000
        Faulting instruction address: 0xc00000000029d800
        Oops: Kernel access of bad area, sig: 11 [#1]
        LE SMP NR_CPUS=2048 NUMA PowerNV
        ...
        CPU: 68 PID: 96584 Comm: cat Kdump: loaded Tainted: G        W
        NIP:  c00000000029d800 LR: c00000000029dac4 CTR: c0000000001e6ad0
        REGS: c0002017fae8ba10 TRAP: 0300   Tainted: G        W
        MSR:  9000000000009033 <SF,HV,EE,ME,IR,DR,RI,LE>  CR: 28022422  XER: 20040000
        CFAR: c00000000029d90c DAR: 0000000000000000 DSISR: 40000000 IRQMASK: 0
        ...
        NIP [c00000000029d800] t_probe_next+0x60/0x180
        LR [c00000000029dac4] t_mod_start+0x1a4/0x1f0
        Call Trace:
        [c0002017fae8bc90] [c000000000cdbc40] _cond_resched+0x10/0xb0 (unreliable)
        [c0002017fae8bce0] [c0000000002a15b0] t_start+0xf0/0x1c0
        [c0002017fae8bd30] [c0000000004ec2b4] seq_read+0x184/0x640
        [c0002017fae8bdd0] [c0000000004a57bc] sys_read+0x10c/0x300
        [c0002017fae8be30] [c00000000000b388] system_call+0x5c/0x70
      
      The test (ftrace_set_ftrace_filter.sh) is part of ftrace stress tests
      and the crash happens when the test does 'cat
      $TRACING_PATH/set_ftrace_filter'.
      
      The address points to the second line below, in t_probe_next(), where
      filter_hash is dereferenced:
        hash = iter->probe->ops.func_hash->filter_hash;
        size = 1 << hash->size_bits;
      
      This happens due to a race with register_ftrace_function_probe(). A new
      ftrace_func_probe is created and added into the func_probes list in
      trace_array under ftrace_lock. However, before initializing the filter,
      we drop ftrace_lock, and re-acquire it after acquiring regex_lock. If
      another process is trying to read set_ftrace_filter, it will be able to
      acquire ftrace_lock during this window and it will end up seeing a NULL
      filter_hash.
      
      Fix this by just checking for a NULL filter_hash in t_probe_next(). If
      the filter_hash is NULL, then this probe is just being added and we can
      simply return from here.
      
      Link: http://lkml.kernel.org/r/05e021f757625cbbb006fad41380323dbe4e3b43.1562249521.git.naveen.n.rao@linux.vnet.ibm.com
      
      Cc: stable@vger.kernel.org
      Fixes: 7b60f3d8 ("ftrace: Dynamically create the probe ftrace_ops for the trace_array")
      Signed-off-by: default avatarNaveen N. Rao <naveen.n.rao@linux.vnet.ibm.com>
      Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      7bd46644
  6. 25 Aug, 2019 1 commit