I compiled with AddressSanitizer and I had these memory leaks while I
was using the tep_parse_format function:
Direct leak of 28 byte(s) in 4 object(s) allocated from:
#0 0x7fb07db49ffe in __interceptor_realloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dffe)
#1 0x7fb07a724228 in extend_token /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:985
#2 0x7fb07a724c21 in __read_token /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:1140
#3 0x7fb07a724f78 in read_token /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:1206
#4 0x7fb07a725191 in __read_expect_type /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:1291
#5 0x7fb07a7251df in read_expect_type /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:1299
#6 0x7fb07a72e6c8 in process_dynamic_array_len /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:2849
#7 0x7fb07a7304b8 in process_function /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:3161
#8 0x7fb07a730900 in process_arg_token /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:3207
#9 0x7fb07a727c0b in process_arg /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:1786
#10 0x7fb07a731080 in event_read_print_args /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:3285
#11 0x7fb07a731722 in event_read_print /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:3369
#12 0x7fb07a740054 in __tep_parse_format /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:6335
#13 0x7fb07a74047a in __parse_event /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:6389
#14 0x7fb07a740536 in tep_parse_format /home/pduplessis/repo/linux/tools/lib/traceevent/event-parse.c:6431
#15 0x7fb07a785acf in parse_event ../../../src/fs-src/fs.c:251
#16 0x7fb07a785ccd in parse_systems ../../../src/fs-src/fs.c:284
#17 0x7fb07a786fb3 in read_metadata ../../../src/fs-src/fs.c:593
#18 0x7fb07a78760e in ftrace_fs_source_init ../../../src/fs-src/fs.c:727
#19 0x7fb07d90c19c in add_component_with_init_method_data ../../../../src/lib/graph/graph.c:1048
#20 0x7fb07d90c87b in add_source_component_with_initialize_method_data ../../../../src/lib/graph/graph.c:1127
#21 0x7fb07d90c92a in bt_graph_add_source_component ../../../../src/lib/graph/graph.c:1152
#22 0x55db11aa632e in cmd_run_ctx_create_components_from_config_components ../../../src/cli/babeltrace2.c:2252
#23 0x55db11aa6fda in cmd_run_ctx_create_components ../../../src/cli/babeltrace2.c:2347
#24 0x55db11aa780c in cmd_run ../../../src/cli/babeltrace2.c:2461
#25 0x55db11aa8a7d in main ../../../src/cli/babeltrace2.c:2673
#26 0x7fb07d5460b2 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x270b2)
The token variable in the process_dynamic_array_len function is
allocated in the read_expect_type function, but is not freed before
calling the read_token function.
Free the token variable before calling read_token in order to plug the
leak.
Signed-off-by: Philippe Duplessis-Guindon <pduplessis@efficios.com>
Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Link: https://lore.kernel.org/linux-trace-devel/20200730150236.5392-1-pduplessis@efficios.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Kernel commit dc4e2801d4 (ring-buffer: Redefine the unimplemented
RINGBUF_TYPE_TIME_STAMP) changed the way the ring buffer timestamps work
- after that commit the previously unimplemented RINGBUF_TYPE_TIME_STAMP
type causes the time delta to be used as a timestamp rather than a delta
to be added to the timestamp.
The trace-cmd code didn't get updated to handle this, so misinterprets
the event data for this case, which causes a cascade of errors,
including trace-report not being able to identify synthetic (or any
other) events generated by the histogram code (which uses TIME_STAMP
mode). For example, the following triggers along with the trace-cmd
shown cause an UNKNOWN_EVENT error and trace-cmd report crash:
# echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > /sys/kernel/debug/tracing/synthetic_events
# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_wakeup).trace(wakeup_latency,$wakeup_lat,next_pid,next_comm) if next_comm=="ping"' > /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
# echo 'hist:keys=comm,pid,lat:wakeup_lat=lat:sort=lat' > /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
# trace-cmd record -e wakeup_latency -e sched_wakeup -f comm==\"ping\" ping localhost -c 5
# trace-cmd report
CPU 0 is empty
CPU 1 is empty
CPU 2 is empty
CPU 3 is empty
CPU 5 is empty
CPU 6 is empty
CPU 7 is empty
cpus=8
ug! no event found for type 0
[UNKNOWN TYPE 0]
ug! no event found for type 11520
Segmentation fault (core dumped)
After this patch we get the correct interpretation and the events are
shown properly:
# trace-cmd report
CPU 0 is empty
CPU 1 is empty
CPU 2 is empty
CPU 3 is empty
CPU 5 is empty
CPU 6 is empty
CPU 7 is empty
cpus=8
<idle>-0 [004] 23284.341392: sched_wakeup: ping:12031 [120] success=1 CPU:004
<idle>-0 [004] 23284.341464: wakeup_latency: lat=58, pid=12031, comm=ping
<idle>-0 [004] 23285.365303: sched_wakeup: ping:12031 [120] success=1 CPU:004
<idle>-0 [004] 23285.365382: wakeup_latency: lat=64, pid=12031, comm=ping
<idle>-0 [004] 23286.389290: sched_wakeup: ping:12031 [120] success=1 CPU:004
<idle>-0 [004] 23286.389378: wakeup_latency: lat=72, pid=12031, comm=ping
<idle>-0 [004] 23287.413213: sched_wakeup: ping:12031 [120] success=1 CPU:004
<idle>-0 [004] 23287.413291: wakeup_latency: lat=64, pid=12031, comm=ping
Link: http://lkml.kernel.org/r/1567628224.13841.4.camel@kernel.org
Link: http://lore.kernel.org/linux-trace-devel/20200625100516.365338-3-tz.stoyanov@gmail.com
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
[ Ported from trace-cmd.git ]
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: linux-trace-devel@vger.kernel.org
Link: http://lore.kernel.org/lkml/20200702185703.785094515@goodmis.org
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
According to the API, if memory allocation wasn't possible, or some
other error occurs, asprintf will return -1, and the contents of strp
below are undefined.
int asprintf(char **strp, const char *fmt, ...);
This patch takes care of return value of asprintf to make it less error
prone and prevent the following build warning.
ignoring return value of ‘asprintf’, declared with attribute warn_unused_result [-Wunused-result]
Signed-off-by: He Zhe <zhe.he@windriver.com>
Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Cc: Tzvetomir Stoyanov <tstoyanov@vmware.com>
Cc: hewenliang4@huawei.com
Link: http://lore.kernel.org/lkml/1582163930-233692-1-git-send-email-zhe.he@windriver.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Pull SPDX updates from Greg KH:
"Here are three SPDX patches for 5.7-rc1.
One fixes up the SPDX tag for a single driver, while the other two go
through the tree and add SPDX tags for all of the .gitignore files as
needed.
Nothing too complex, but you will get a merge conflict with your
current tree, that should be trivial to handle (one file modified by
two things, one file deleted.)
All three of these have been in linux-next for a while, with no
reported issues other than the merge conflict"
* tag 'spdx-5.7-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/spdx:
ASoC: MT6660: make spdxcheck.py happy
.gitignore: add SPDX License Identifier
.gitignore: remove too obvious comments
If the precision of print_event_time() is zero or greater than the
timestamp, it uses a different format. But that format had an extra new
line at the end, and caused the output to not look right:
cpus=2
sleep-3946 [001]111264306005
: function: inotify_inode_queue_event
sleep-3946 [001]111264307158
: function: __fsnotify_parent
sleep-3946 [001]111264307637
: function: inotify_dentry_parent_queue_event
sleep-3946 [001]111264307989
: function: fsnotify
sleep-3946 [001]111264308401
: function: audit_syscall_exit
Fixes: 38847db974 ("libtraceevent, perf tools: Changes in tep_print_event_* APIs")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Link: http://lore.kernel.org/lkml/20200303231852.6ab6882f@oasis.local.home
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
When we use 'O=' with make to build libtraceevent in a separate folder
it fails to install libtraceevent.a and libtraceevent.so.1.1.0 with the
error:
INSTALL /home/sudip/linux/obj-trace/libtraceevent.a
INSTALL /home/sudip/linux/obj-trace/libtraceevent.so.1.1.0
cp: cannot stat 'libtraceevent.a': No such file or directory
Makefile:225: recipe for target 'install_lib' failed
make: *** [install_lib] Error 1
I used the command:
make O=../../../obj-trace DESTDIR=~/test prefix==/usr install
It turns out libtraceevent Makefile, even though it builds in a separate
folder, searches for libtraceevent.a and libtraceevent.so.1.1.0 in its
source folder.
So, add the 'OUTPUT' prefix to the source path so that 'make' looks for
the files in the correct place.
Signed-off-by: Sudipm Mukherjee <sudipm.mukherjee@gmail.com>
Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Cc: linux-trace-devel@vger.kernel.org
Link: http://lore.kernel.org/lkml/20191115113610.21493-1-sudipm.mukherjee@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
When we passed some location in DESTDIR, install_headers called
do_install with DESTDIR as part of the second argument.
But do_install is again using '$(DESTDIR_SQ)$2', so as a result the
headers were installed in a location $DESTDIR/$DESTDIR.
In my testing I passed DESTDIR=/home/sudip/test and the headers were
installed in: /home/sudip/test/home/sudip/test/usr/include/traceevent.
Lets remove DESTDIR from the second argument of do_install so that the
headers are installed in the correct location.
Signed-off-by: Sudipm Mukherjee <sudipm.mukherjee@gmail.com>
Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Cc: Sudipm Mukherjee <sudipm.mukherjee@gmail.com>
Cc: linux-trace-devel@vger.kernel.org
Link: http://lore.kernel.org/lkml/20191114133719.309-1-sudipm.mukherjee@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Libtraceevent APIs for printing various trace events information are
complicated, there are complex extra parameters. To control the way
event information is printed, the user should call a set of functions in
a specific sequence.
These APIs are reimplemented to provide a more simple interface for
printing event information.
Removed APIs:
tep_print_event_task()
tep_print_event_time()
tep_print_event_data()
tep_event_info()
tep_is_latency_format()
tep_set_latency_format()
tep_data_latency_format()
tep_set_print_raw()
A new API for printing event information is introduced:
void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
struct tep_record *record, const char *fmt, ...);
where "fmt" is a printf-like format string, followed by the event
fields to be printed. Supported fields:
TEP_PRINT_PID, "%d" - event PID
TEP_PRINT_CPU, "%d" - event CPU
TEP_PRINT_COMM, "%s" - event command string
TEP_PRINT_NAME, "%s" - event name
TEP_PRINT_LATENCY, "%s" - event latency
TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
can be specified as part of this format string:
"%precision.divisord". Example:
"%3.1000d" - divide the time by 1000 and print the first 3 digits
before the dot. Thus, the time stamp "123456000" will be printed as
"123.456"
TEP_PRINT_INFO, "%s" - event information.
TEP_PRINT_INFO_RAW, "%s" - event information, in raw format.
Example:
tep_print_event(tep, s, record, "%16s-%-5d [%03d] %s %6.1000d %s %s",
TEP_PRINT_COMM, TEP_PRINT_PID, TEP_PRINT_CPU,
TEP_PRINT_LATENCY, TEP_PRINT_TIME, TEP_PRINT_NAME, TEP_PRINT_INFO);
Output:
ls-11314 [005] d.h. 185207.366383 function __wake_up
Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: linux-trace-devel@vger.kernel.org
Cc: Patrick McLean <chutzpah@gentoo.org>
Link: http://lore.kernel.org/linux-trace-devel/20190801074959.22023-2-tz.stoyanov@gmail.com
Link: http://lore.kernel.org/lkml/20190805204355.041132030@goodmis.org
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
While reading a trace data file that had 100,000s of tasks, the process
took an extremely long time. I profiled it down to add_new_comm(), which
was doing a qsort() call on an array that was pretty much already sorted
(all but the last element. qsort() isn't very efficient when dealing
with mostly sorted arrays, and this definitely showed its issues.
When adding a new task to the task list, instead of using qsort(), do
another bsearch() with a function that will find the element before
where the new task will be inserted in. Then simply shift the rest of
the array, and insert the task where it belongs.
Fixes: f7d82350e5 ("tools/events: Add files to create libtraceevent.a")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: linux-trace-devel@vger.kernel.org
Link: http://lkml.kernel.org/r/20190828191820.127233764@goodmis.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
