Coming in v3.16, trace events will be able to save bitmasks in raw
format in the ring buffer and output it with the __get_bitmask() macro.
In order for userspace tools to parse this, it must be able to handle
the __get_bitmask() call and be able to convert the data that's in
the ring buffer into a nice bitmask format. The output is similar to
what the kernel uses to print bitmasks, with a comma separator every
4 bytes (8 characters).
This allows for cpumasks to also be saved efficiently.
The first user is the thermal:thermal_power_limit event which has the
following output:
thermal_power_limit: cpus=0000000f freq=1900000 cdev_state=0 power=5252
Link: http://lkml.kernel.org/r/20140506132238.22e136d1@gandalf.local.home
Suggested-by: Javi Merino <javi.merino@arm.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Acked-by: Namhyung Kim <namhyung@kernel.org>
Tested-by: Javi Merino <javi.merino@arm.com>
Link: http://lkml.kernel.org/r/20140603032224.229186537@goodmis.org
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
Commit 12e55569a2 "tools lib traceevent: Use helper trace-seq in print
functions like kernel does" added a extra trace_seq helper to process
string arguments like the kernel does it. But the difference between the
kernel and the userspace library is that the kernel's trace_seq structure
has a static allocated buffer. The userspace one has a dynamically
allocated one. It requires a trace_seq_destroy(), otherwise it produces
a nasty memory leak.
Cc: stable@vger.kernel.org # 3.14+
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/20140422192330.6bb09bf8@gandalf.local.home
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
It's sometimes useful to know where the parse failure was occurred. Add
do_warning_event() macro to see the failing event.
It now shows the messages like below:
$ perf test 5
5: parse events tests : Warning: [kvmmmu:kvm_mmu_get_page] bad op token {
Warning: [kvmmmu:kvm_mmu_sync_page] bad op token {
Warning: [kvmmmu:kvm_mmu_unsync_page] bad op token {
Warning: [kvmmmu:kvm_mmu_prepare_zap_page] bad op token {
Warning: [kvmmmu:fast_page_fault] function is_writable_pte not defined
Warning: [xen:xen_mmu_ptep_modify_prot_commit] function sizeof not defined
Warning: [xen:xen_mmu_ptep_modify_prot_start] function sizeof not defined
Warning: [xen:xen_mmu_set_pgd] function sizeof not defined
Warning: [xen:xen_mmu_set_pud] function sizeof not defined
Warning: [xen:xen_mmu_set_pmd] function sizeof not defined
...
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung.kim@lge.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Ramkumar Ramachandra <artagnon@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/1395192174-26273-1-git-send-email-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
When Jiri Olsa was writing a function callback for
scsi_trace_parse_cdb(), he thought that the traceevent library had a
bug in it because he was getting this error:
Error: expected ')' but read ','
Error: expected ')' but read ','
Error: expected ')' but read ','
Error: expected ')' but read ','
But in truth, he didn't have the write number of arguments for the
function callback, and the error was the library detecting the
discrepancy. A better error message would have prevented the confusion:
Error: function 'scsi_trace_parse_cdb()' only expects 2 arguments but event scsi_dispatch_cmd_timeout has more
Error: function 'scsi_trace_parse_cdb()' only expects 2 arguments but event scsi_dispatch_cmd_start has more
Error: function 'scsi_trace_parse_cdb()' only expects 2 arguments but event scsi_dispatch_cmd_error has more
Error: function 'scsi_trace_parse_cdb()' only expects 2 arguments but event scsi_dispatch_cmd_done has more
Or
Error: function 'scsi_trace_parse_cdb()' expects 4 arguments but event scsi_dispatch_cmd_timeout only uses 3
Error: function 'scsi_trace_parse_cdb()' expects 4 arguments but event scsi_dispatch_cmd_start only uses 3
Error: function 'scsi_trace_parse_cdb()' expects 4 arguments but event scsi_dispatch_cmd_error only uses 3
Error: function 'scsi_trace_parse_cdb()' expects 4 arguments but event scsi_dispatch_cmd_done only uses 3
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/n/tip-a4c34w62vl0diitvxb7bt3er@git.kernel.org
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Jiri Olsa reported that his plugin for scsi was chopping off part of the
output. Investigating this, I found that Jiri used the same functions as
what is in the kernel, which adds the following:
trace_seq_putc(p, 0);
This adds a '\0' to the output string. The reason this works in the
kernel is that the "p" that is passed to the function helper is a
temporary trace_seq. But in the libtraceevent library, it's the pointer
to the trace_seq used to output. By adding the '\0', it truncates the
line and nothing added after that will be printed.
We can solve this in two ways. One is to have the helper functions for
the library not add the unnecessary '\0'. The other is to change the
library to also use a helper trace_seq structure that gets copied to the
main trace_seq just like the kernel does.
The latter allows the helper functions in the plugins to be the same as
the kernel, which is the better solution.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Reported-by: Jiri Olsa <jolsa@redhat.com>
Tested-by: Jiri Olsa <jolsa@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Link: http://lkml.kernel.org/r/20131119182937.401668e3@gandalf.local.home
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
gcc complaint on 32-bit system:
/home/acme/git/linux/tools/lib/traceevent/event-parse.c: In function ‘eval_num_arg’:
/home/acme/git/linux/tools/lib/traceevent/event-parse.c:3468:9: warning: cast from pointer to integer of different size [-Wpointer-to-int-cast]
This is because the eval_num_arg returns everything as an 'unsigned long long',
so it converts a void pointer to a wider integer, fix it by converting the void
pointer to an integer of the same size, 'unsigned long', before casting it to
'unsigned long long'.
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-yllx4aqcg06v5n4vjpwiiuld@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Jiri Olsa reported that the scsi_dispatch_cmd_done event failed to parse
with:
Error: expected type 5 but read 4
Error: expected type 5 but read 4
The problem is with this part of the print_fmt:
__print_symbolic(((REC->result) >> 24) & 0xff, ...
The __print_symbolic() helper function's first parameter is the field to
use to determine what symbol to print based on the value of the result.
The parser can handle one operation, but it can not handle multiple
operations ('>>' and '&').
Add code to process all operations for the field argument for
__print_symbolic() as well as __print_flags().
Reported-by: Jiri Olsa <jolsa@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Link: http://lkml.kernel.org/r/20131118142314.27ca334b@gandalf.local.home
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Jiri Olsa was writing a plugin for the cfg80211_tx_mlme_mgmt trace
event, and was not able to get the implemented function working.
The event's print fmt looks like:
"netdev:%s(%d), ftype:0x%.2x", REC->name, REC->ifindex,
__le16_to_cpup((__le16 *)__get_dynamic_array(frame))
As there's no helper function for __le16_to_cpup(), Jiri was creating one
with a plugin. But unfortunately, it would not work even though he set
up the plugin correctly.
The problem is that the function parameters do not handle the helper
function "__get_dynamic_array()", and that passes in a NULL pointer.
Adding PRINT_DYNAMIC_ARRAY direct support to eval_num_arg() allows the
use of __get_dynamic_array() in function parameters.
Reported-by: Jiri Olsa <jolsa@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Tested-by: Jiri Olsa <jolsa@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Link: http://lkml.kernel.org/r/20131111160810.0ba9df7d@gandalf.local.home
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Currently when using the raw format for fields, when looking at a
character array, to determine if it is a string or not, we make sure all
characters are "isprint()". If not, then we consider it a numeric array,
and print the hex numbers of the characters instead.
But it seems that '\n' fails the isprint() check! Add isspace() to the
check as well, such that if all characters pass isprint() or isspace()
it will assume the character array is a string.
Reported-by: Xenia Ragiadakou <burzalodowa@gmail.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xenia Ragiadakou <burzalodowa@gmail.com>
Link: http://lkml.kernel.org/r/20131101215501.465091682@goodmis.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
The trace_bprintk() in the kernel looks like:
ring_buffer_producer_thread: Missed: 0
ring_buffer_producer_thread: Hit: 62174350
ring_buffer_producer_thread: Entries per millisec: 6296
ring_buffer_producer_thread: 158 ns per entry
ring_buffer_producer_thread: Sleeping for 10 secs
ring_buffer_producer_thread: Starting ring buffer hammer
ring_buffer_producer_thread: End ring buffer hammer
But the current output looks like this:
ring_buffer_producer_thread : Time: 9407018 (usecs)
ring_buffer_producer_thread : Overruns: 43285485
ring_buffer_producer_thread : Read: 4405365 (by events)
ring_buffer_producer_thread : Entries: 0
ring_buffer_producer_thread : Total: 47690850
ring_buffer_producer_thread : Missed: 0
ring_buffer_producer_thread : Hit: 47690850
Remove the space between the function and the colon.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Link: http://lkml.kernel.org/r/20131101215501.272654481@goodmis.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
The kernel has a few events with a format similar to this excerpt:
field:unsigned int len; offset:12; size:4; signed:0;
field:__data_loc unsigned char[] data_array; offset:16; size:4; signed:0;
print fmt: "%s", __print_hex(__get_dynamic_array(data_array), REC->len)
trace-cmd could already parse that arg correctly, but print_str_arg()
was unable to handle the first parameter being a dynamic array. (It
just printed a "field not found" warning).
Teach print_str_arg's PRINT_HEX case to handle the nested
PRINT_DYNAMIC_ARRAY correctly. The output now matches the kernel's own
formatting for this case.
Signed-off-by: Howard Cochran <hcochran@lexmark.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Link: http://lkml.kernel.org/r/1381503349-12271-1-git-send-email-hcochran@lexmark.com
[ Removed "polish compare", we don't do that here ]
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
For some reason the libtraceevent tracepoint-parsing code is missing
the FIELD_IS_SIGNED flag-setting code, which causes problems for the
Perl trace event binding at least, since it ends up unable to
recognize negative numbers.
Things like checking for negative return values therefore fail, causing
scripts like rwtop to instead interpret the negative return value as a
large positive value, which in turn get added to e.g. read totals with
insanely invalid results.
So set the FIELD_IS_SIGNED flag for tracepoint events that specify
"signed:1".
Before:
# perf script record rw-by-pid
# perf script report rw-by-pid
read counts by pid:
pid comm # reads bytes_requested bytes_read
------ -------------------- ----------- ---------- ----------
753 Xorg 88 512000 7.74763251095801e+20
1619 firefox 42 462 2.58254417031934e+20
1232 gnome-shell 11 176 1.10680464442257e+20
1471 gnome-terminal 3 16366 18446744073709551615
1408 libsocialweb-co 2 32 18446744073709551613
After:
# perf script report rw-by-pid
read counts by pid:
pid comm # reads bytes_requested bytes_read
------ -------------------- ----------- ---------- ----------
753 Xorg 88 512000 2764
1619 firefox 42 462 126
1232 gnome-shell 11 176 40
1471 gnome-terminal 3 16366 10
1408 libsocialweb-co 2 32 8
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
Link: http://lkml.kernel.org/r/1471b5968821a455cf5168bb4567964e74ecf530.1358527965.git.tom.zanussi@linux.intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
