1. 28 Sep, 2019 1 commit
    • Masami Hiramatsu's avatar
      tracing/probe: Fix to check the difference of nr_args before adding probe · d2aea95a
      Masami Hiramatsu authored
      Steven reported that a test triggered:
      
      ==================================================================
       BUG: KASAN: slab-out-of-bounds in trace_kprobe_create+0xa9e/0xe40
       Read of size 8 at addr ffff8880c4f25a48 by task ftracetest/4798
      
       CPU: 2 PID: 4798 Comm: ftracetest Not tainted 5.3.0-rc6-test+ #30
       Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016
       Call Trace:
        dump_stack+0x7c/0xc0
        ? trace_kprobe_create+0xa9e/0xe40
        print_address_description+0x6c/0x332
        ? trace_kprobe_create+0xa9e/0xe40
        ? trace_kprobe_create+0xa9e/0xe40
        __kasan_report.cold.6+0x1a/0x3b
        ? trace_kprobe_create+0xa9e/0xe40
        kasan_report+0xe/0x12
        trace_kprobe_create+0xa9e/0xe40
        ? print_kprobe_event+0x280/0x280
        ? match_held_lock+0x1b/0x240
        ? find_held_lock+0xac/0xd0
        ? fs_reclaim_release.part.112+0x5/0x20
        ? lock_downgrade+0x350/0x350
        ? kasan_unpoison_shadow+0x30/0x40
        ? __kasan_kmalloc.constprop.6+0xc1/0xd0
        ? trace_kprobe_create+0xe40/0xe40
        ? trace_kprobe_create+0xe40/0xe40
        create_or_delete_trace_kprobe+0x2e/0x60
        trace_run_command+0xc3/0xe0
        ? trace_panic_handler+0x20/0x20
        ? kasan_unpoison_shadow+0x30/0x40
        trace_parse_run_command+0xdc/0x163
        vfs_write+0xe1/0x240
        ksys_write+0xba/0x150
        ? __ia32_sys_read+0x50/0x50
        ? tracer_hardirqs_on+0x61/0x180
        ? trace_hardirqs_off_caller+0x43/0x110
        ? mark_held_locks+0x29/0xa0
        ? do_syscall_64+0x14/0x260
        do_syscall_64+0x68/0x260
      
      Fix to check the difference of nr_args before adding probe
      on existing probes. This also may set the error log index
      bigger than the number of command parameters. In that case
      it sets the error position is next to the last parameter.
      
      Link: http://lkml.kernel.org/r/156966474783.3478.13217501608215769150.stgit@devnote2
      
      Fixes: ca89bc07 ("tracing/kprobe: Add multi-probe per event support")
      Reported-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      Signed-off-by: default avatarMasami Hiramatsu <mhiramat@kernel.org>
      Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
      d2aea95a
  2. 25 Sep, 2019 1 commit
  3. 19 Sep, 2019 3 commits
  4. 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
  5. 05 Sep, 2019 1 commit
  6. 31 Aug, 2019 28 commits
  7. 30 Aug, 2019 1 commit