[RFC,2/2] trace: allocate temparary buffer for trace output usage
Commit Message
there is one dwc3 trace event declare as below,
DECLARE_EVENT_CLASS(dwc3_log_event,
TP_PROTO(u32 event, struct dwc3 *dwc),
TP_ARGS(event, dwc),
TP_STRUCT__entry(
__field(u32, event)
__field(u32, ep0state)
__dynamic_array(char, str, DWC3_MSG_MAX)
),
TP_fast_assign(
__entry->event = event;
__entry->ep0state = dwc->ep0state;
),
TP_printk("event (%08x): %s", __entry->event,
dwc3_decode_event(__get_str(str), DWC3_MSG_MAX,
__entry->event, __entry->ep0state))
);
the problem is when trace function called, it will allocate up to
DWC3_MSG_MAX bytes from trace event buffer, but never fill the buffer
during fast assignment, it only fill the buffer when output function are
called, so this means if output function are not called, the buffer will
never used.
add __alloc_buf() and __get_buf() which will not allocate event buffer
when trace function called, but when trace output function called, it will
kmalloc buffer with size DWC3_MSG_MAX for temprary usage and free it
before trace output function return.
Signed-off-by: Linyu Yuan <quic_linyyuan@quicinc.com>
---
include/trace/stages/stage1_struct_define.h | 5 +++
include/trace/stages/stage3_trace_output.h | 60 +++++++++++++++++++++++++++++
include/trace/stages/stage4_event_fields.h | 6 +++
include/trace/stages/stage7_class_define.h | 1 +
include/trace/trace_events.h | 29 +++++++++++++-
5 files changed, 100 insertions(+), 1 deletion(-)
Comments
On Wed, 14 Dec 2022 22:11:42 +0800
Linyu Yuan <quic_linyyuan@quicinc.com> wrote:
> there is one dwc3 trace event declare as below,
> DECLARE_EVENT_CLASS(dwc3_log_event,
> TP_PROTO(u32 event, struct dwc3 *dwc),
> TP_ARGS(event, dwc),
> TP_STRUCT__entry(
> __field(u32, event)
> __field(u32, ep0state)
> __dynamic_array(char, str, DWC3_MSG_MAX)
> ),
> TP_fast_assign(
> __entry->event = event;
> __entry->ep0state = dwc->ep0state;
> ),
> TP_printk("event (%08x): %s", __entry->event,
> dwc3_decode_event(__get_str(str), DWC3_MSG_MAX,
> __entry->event, __entry->ep0state))
> );
> the problem is when trace function called, it will allocate up to
> DWC3_MSG_MAX bytes from trace event buffer, but never fill the buffer
> during fast assignment, it only fill the buffer when output function are
> called, so this means if output function are not called, the buffer will
> never used.
>
> add __alloc_buf() and __get_buf() which will not allocate event buffer
> when trace function called, but when trace output function called, it will
> kmalloc buffer with size DWC3_MSG_MAX for temprary usage and free it
> before trace output function return.
This looks exactly like what the trace_seq *p is to be used for.
static notrace enum print_line_t \
trace_raw_output_##call(struct trace_iterator *iter, int flags, \
struct trace_event *trace_event) \
{ \
struct trace_seq *s = &iter->seq; \
struct trace_seq __maybe_unused *p = &iter->tmp_seq; \
^^^^^^^^^^^^^^^^^^^^
struct trace_event_raw_##call *field; \
int ret; \
\
field = (typeof(field))iter->ent; \
\
ret = trace_raw_output_prep(iter, trace_event); \
if (ret != TRACE_TYPE_HANDLED) \
return ret; \
\
trace_event_printf(iter, print); \
\
return trace_handle_return(s); \
} \
That is a trace_seq buffer that is for temporary usage during the output.
See:
include/trace/events/libata.h
include/trace/events/scsi.h
As well as the macros trace_print_bitmask_seq(), trace_print_flags_seq(),
trace_print_symbols_seq(), etc.
-- Steve
thanks for remind, will check and use it.
thanks
On 12/14/2022 10:25 PM, Steven Rostedt wrote:
> On Wed, 14 Dec 2022 22:11:42 +0800
> Linyu Yuan <quic_linyyuan@quicinc.com> wrote:
>
>> there is one dwc3 trace event declare as below,
>> DECLARE_EVENT_CLASS(dwc3_log_event,
>> TP_PROTO(u32 event, struct dwc3 *dwc),
>> TP_ARGS(event, dwc),
>> TP_STRUCT__entry(
>> __field(u32, event)
>> __field(u32, ep0state)
>> __dynamic_array(char, str, DWC3_MSG_MAX)
>> ),
>> TP_fast_assign(
>> __entry->event = event;
>> __entry->ep0state = dwc->ep0state;
>> ),
>> TP_printk("event (%08x): %s", __entry->event,
>> dwc3_decode_event(__get_str(str), DWC3_MSG_MAX,
>> __entry->event, __entry->ep0state))
>> );
>> the problem is when trace function called, it will allocate up to
>> DWC3_MSG_MAX bytes from trace event buffer, but never fill the buffer
>> during fast assignment, it only fill the buffer when output function are
>> called, so this means if output function are not called, the buffer will
>> never used.
>>
>> add __alloc_buf() and __get_buf() which will not allocate event buffer
>> when trace function called, but when trace output function called, it will
>> kmalloc buffer with size DWC3_MSG_MAX for temprary usage and free it
>> before trace output function return.
> This looks exactly like what the trace_seq *p is to be used for.
>
> static notrace enum print_line_t \
> trace_raw_output_##call(struct trace_iterator *iter, int flags, \
> struct trace_event *trace_event) \
> { \
> struct trace_seq *s = &iter->seq; \
> struct trace_seq __maybe_unused *p = &iter->tmp_seq; \
> ^^^^^^^^^^^^^^^^^^^^
>
> struct trace_event_raw_##call *field; \
> int ret; \
> \
> field = (typeof(field))iter->ent; \
> \
> ret = trace_raw_output_prep(iter, trace_event); \
> if (ret != TRACE_TYPE_HANDLED) \
> return ret; \
> \
> trace_event_printf(iter, print); \
> \
> return trace_handle_return(s); \
> } \
>
> That is a trace_seq buffer that is for temporary usage during the output.
>
> See:
> include/trace/events/libata.h
> include/trace/events/scsi.h
>
> As well as the macros trace_print_bitmask_seq(), trace_print_flags_seq(),
> trace_print_symbols_seq(), etc.
>
> -- Steve
>
is it possible add a generic macro like #define __get_buf(offset, len)
(p->buffer + (offset)) ?
it only use buffer filed of struct trace_seq .
On 12/15/2022 9:22 AM, Linyu Yuan wrote:
> thanks for remind, will check and use it.
>
>
> thanks
>
> On 12/14/2022 10:25 PM, Steven Rostedt wrote:
>> On Wed, 14 Dec 2022 22:11:42 +0800
>> Linyu Yuan <quic_linyyuan@quicinc.com> wrote:
>>
>>> there is one dwc3 trace event declare as below,
>>> DECLARE_EVENT_CLASS(dwc3_log_event,
>>> TP_PROTO(u32 event, struct dwc3 *dwc),
>>> TP_ARGS(event, dwc),
>>> TP_STRUCT__entry(
>>> __field(u32, event)
>>> __field(u32, ep0state)
>>> __dynamic_array(char, str, DWC3_MSG_MAX)
>>> ),
>>> TP_fast_assign(
>>> __entry->event = event;
>>> __entry->ep0state = dwc->ep0state;
>>> ),
>>> TP_printk("event (%08x): %s", __entry->event,
>>> dwc3_decode_event(__get_str(str), DWC3_MSG_MAX,
>>> __entry->event, __entry->ep0state))
>>> );
>>> the problem is when trace function called, it will allocate up to
>>> DWC3_MSG_MAX bytes from trace event buffer, but never fill the buffer
>>> during fast assignment, it only fill the buffer when output function
>>> are
>>> called, so this means if output function are not called, the buffer
>>> will
>>> never used.
>>>
>>> add __alloc_buf() and __get_buf() which will not allocate event buffer
>>> when trace function called, but when trace output function called,
>>> it will
>>> kmalloc buffer with size DWC3_MSG_MAX for temprary usage and free it
>>> before trace output function return.
>> This looks exactly like what the trace_seq *p is to be used for.
>>
>> static notrace enum print_line_t \
>> trace_raw_output_##call(struct trace_iterator *iter, int flags, \
>> struct trace_event *trace_event) \
>> { \
>> struct trace_seq *s = &iter->seq; \
>> struct trace_seq __maybe_unused *p = &iter->tmp_seq; \
>> ^^^^^^^^^^^^^^^^^^^^
>>
>> struct trace_event_raw_##call *field; \
>> int ret; \
>> \
>> field = (typeof(field))iter->ent; \
>> \
>> ret = trace_raw_output_prep(iter, trace_event); \
>> if (ret != TRACE_TYPE_HANDLED) \
>> return ret; \
>> \
>> trace_event_printf(iter, print); \
>> \
>> return trace_handle_return(s); \
>> } \
>>
>> That is a trace_seq buffer that is for temporary usage during the
>> output.
>>
>> See:
>> include/trace/events/libata.h
>> include/trace/events/scsi.h
>>
>> As well as the macros trace_print_bitmask_seq(),
>> trace_print_flags_seq(),
>> trace_print_symbols_seq(), etc.
>>
>> -- Steve
>>
On Thu, 15 Dec 2022 09:53:27 +0800
Linyu Yuan <quic_linyyuan@quicinc.com> wrote:
> is it possible add a generic macro like #define __get_buf(offset, len)
> (p->buffer + (offset)) ?
>
> it only use buffer filed of struct trace_seq .
If it works for you, I guess. I'd like to see the patch and use case.
-- Steve
@@ -56,5 +56,10 @@
#undef __rel_sockaddr
#define __rel_sockaddr(field, len) __rel_dynamic_array(u8, field, len)
+#undef __alloc_buf
+#define __alloc_buf(len)
+
+/* __get_buf is not allow present inside TP_STRUCT__entry */
+
#undef TP_STRUCT__entry
#define TP_STRUCT__entry(args...) args
@@ -139,3 +139,63 @@
u64 ____val = (u64)(value); \
(u32) do_div(____val, NSEC_PER_SEC); \
})
+
+#undef __field
+#define __field(type, item)
+
+#undef __field_ext
+#define __field_ext(type, item, filter_type)
+
+#undef __field_struct
+#define __field_struct(type, item)
+
+#undef __field_struct_ext
+#define __field_struct_ext(type, item, filter_type)
+
+#undef __array
+#define __array(type, item, len)
+
+#undef __dynamic_array
+#define __dynamic_array(type, item, len)
+
+#undef __string
+#define __string(item, src)
+
+#undef __string_len
+#define __string_len(item, src, len)
+
+#undef __vstring
+#define __vstring(item, fmt, ap)
+
+#undef __bitmask
+#define __bitmask(item, nr_bits)
+
+#undef __cpumask
+#define __cpumask(item)
+
+#undef __sockaddr
+#define __sockaddr(field, len)
+
+#undef __rel_dynamic_array
+#define __rel_dynamic_array(type, item, len)
+
+#undef __rel_string
+#define __rel_string(item, src)
+
+#undef __rel_string_len
+#define __rel_string_len(item, src, len)
+
+#undef __rel_bitmask
+#define __rel_bitmask(item, nr_bits)
+
+#undef __rel_cpumask
+#define __rel_cpumask(item)
+
+#undef __rel_sockaddr
+#define __rel_sockaddr(field, len)
+
+#undef __alloc_buf
+#define __alloc_buf(len) __buf_len = (len);
+
+#undef __get_buf
+#define __get_buf(offset) (__buf + (offset))
@@ -72,3 +72,9 @@
#undef __rel_sockaddr
#define __rel_sockaddr(field, len) __rel_dynamic_array(u8, field, len)
+
+#undef __alloc_buf
+#define __alloc_buf(len)
+
+#undef __get_buf
+#define __get_buf(offset)
@@ -23,6 +23,7 @@
#undef __get_rel_sockaddr
#undef __print_array
#undef __print_hex_dump
+#undef __get_buf
/*
* The below is not executed in the kernel. It is only what is
@@ -192,6 +192,8 @@ trace_raw_output_##call(struct trace_iterator *iter, int flags, \
struct trace_seq *s = &iter->seq; \
struct trace_seq __maybe_unused *p = &iter->tmp_seq; \
struct trace_event_raw_##call *field; \
+ void *__buf = NULL; \
+ size_t __buf_len = 0; \
int ret; \
\
field = (typeof(field))iter->ent; \
@@ -200,8 +202,18 @@ trace_raw_output_##call(struct trace_iterator *iter, int flags, \
if (ret != TRACE_TYPE_HANDLED) \
return ret; \
\
+ tstruct; \
+ \
+ if (__buf_len) { \
+ __buf = kmalloc(__buf_len, GFP_KERNEL); \
+ if (!__buf) \
+ return -ENOMEM; \
+ } \
+ \
trace_event_printf(iter, print); \
\
+ kfree(__buf); \
+ \
return trace_handle_return(s); \
} \
static struct trace_event_functions trace_event_type_funcs_##call = { \
@@ -217,6 +229,9 @@ trace_raw_output_##call(struct trace_iterator *iter, int flags, \
struct trace_event_raw_##template *field; \
struct trace_entry *entry; \
struct trace_seq *p = &iter->tmp_seq; \
+ void *__buf = NULL; \
+ size_t __buf_len = 0; \
+ int ret; \
\
entry = iter->ent; \
\
@@ -227,8 +242,20 @@ trace_raw_output_##call(struct trace_iterator *iter, int flags, \
\
field = (typeof(field))entry; \
\
+ tstruct; \
+ \
+ if (__buf_len) { \
+ __buf = kmalloc(__buf_len, GFP_KERNEL); \
+ if (!__buf) \
+ return -ENOMEM; \
+ } \
+ \
trace_seq_init(p); \
- return trace_output_call(iter, #call, print); \
+ ret = trace_output_call(iter, #call, print); \
+ \
+ kfree(__buf); \
+ \
+ return ret; \
} \
static struct trace_event_functions trace_event_type_funcs_##call = { \
.trace = trace_raw_output_##call, \