Xen devel - Jun 2006 - Hi,something about the xentrace tool

Hi folks:

 Recently, I am doing some research on xentrace source code.
 En,actually,I think the xentrace is a very useful tool for xen debug.

 ./xen/include/xen/trace.h
 ./xen/common/trace.c
 etc.
 I got a point very confused in the source code about the trace record.

from man page
            "Where CPU is the processor number, TSC is the record’s
timestamp  (the
            value  of the CPU cycle counter), EVENT is the event ID and
D1...D5 are
            the trace data."

            "Which correspond to the CPU number, event ID, timestamp
counter
and
            the 5 data fields from the trace record.   There should be one
such
            rule for each type of event."

 So I just wonder what does these kind of D1....D5 data mean.

 I found the defined the d1-d5 structure in  xen/include/public/trace.h
 59 /* This structure represents a single trace buffer record. */
 60 struct t_rec {
 61     uint64_t cycles;          /* cycle counter timestamp */
 62     uint32_t event;           /* event ID                */
 63     unsigned long data[5];    /* event data items        */
 64 };

 and defined a trace function in ./xen/common/trace.c
 225 void trace(u32 event, unsigned long d1, unsigned long d2,
 226            unsigned long d3, unsigned long d4, unsigned long d5)
 227 {

 But I still can''t understand what are these data real meaning
  I never found a place in the source code where this function void
trace(...) had been called.

 Can someone give me a clue about this?
 Or are those interfaces (d1...d5) for developers to define their own
interest to track the event?

 Your rapid reply will be appreciated.
 Thanks.

----
Regards


_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel

Search for the "TRACE_nD" macros., where you replace
''n'' with [1-5] to
see how traces are used in practice.  For example,

TRACE_2D(TRC_[sometype], dataval1, dataval2);

This will be changed by the preprocessor into

trace(TRC_[sometype], dataval1, dataval2, 0, 0, 0);

This saves us poor exhausted programmers from typing 3 extra zeros. ;-)

As you surmised, the values in the data are defined per trace value,
depending on what information the programmer writing the trace wants
to gather.

Be advised that xentrace adds the physical cpu that the event occured
on, so the real structure to read from xentrace output looks like
this:

struct trace_record {
    unsigned long cpu;
    unsigned long long tsc;
    unsigned long event;
    unsigned long data[5];
};

Peace,
 -George

On 6/11/06, rickey berkeley <rickey.berkeley@gmail.com>
wrote:
>
> Hi folks:
>
>  Recently, I am doing some research on xentrace source code.
>  En,actually,I think the xentrace is a very useful tool for xen debug.
>
>  ./xen/include/xen/trace.h
>  ./xen/common/trace.c
>  etc.
>  I got a point very confused in the source code about the trace record.
>
> from man page
>             "Where CPU is the processor number, TSC is the record’s
> timestamp  (the
>             value  of the CPU cycle counter), EVENT is the event ID and
> D1...D5 are
>             the trace data."
>
>             "Which correspond to the CPU number, event ID, timestamp
counter
> and
>             the 5 data fields from the trace record.   There should be one
> such
>             rule for each type of event."
>
>  So I just wonder what does these kind of D1....D5 data mean.
>
>  I found the defined the d1-d5 structure in  xen/include/public/trace.h
>  59 /* This structure represents a single trace buffer record. */
>  60 struct t_rec {
>  61     uint64_t cycles;          /* cycle counter timestamp */
>  62     uint32_t event;           /* event ID                */
>  63     unsigned long data[5];    /* event data items        */
>  64 };
>
>  and defined a trace function in ./xen/common/trace.c
>  225 void trace(u32 event, unsigned long d1, unsigned long d2,
>  226            unsigned long d3, unsigned long d4, unsigned long d5)
>  227 {
>
>  But I still can''t understand what are these data real meaning
>   I never found a place in the source code where this function void
> trace(...) had been called.
>
>  Can someone give me a clue about this?
>  Or are those interfaces (d1...d5) for developers to define their own
> interest to track the event?
>
>  Your rapid reply will be appreciated.
>  Thanks.
>
> ----
> Regards
>
>
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xensource.com
> http://lists.xensource.com/xen-devel
>
>
>
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel

* rickey berkeley <rickey.berkeley@gmail.com> [2006-06-11
08:18]:
> Hi folks:
Hi,
> from man page
>            "Where CPU is the processor number, TSC is the recordâ??s
> timestamp  (the
>            value  of the CPU cycle counter), EVENT is the event ID and
> D1...D5 are
>            the trace data."
> 
>            "Which correspond to the CPU number, event ID, timestamp
counter
> and
>            the 5 data fields from the trace record.   There should be one
> such
>            rule for each type of event."
> 
> So I just wonder what does these kind of D1....D5 data mean.
This is referring to the fact that a trace record can have up to 5
fields.
> 
> I found the defined the d1-d5 structure in  xen/include/public/trace.h
> 59 /* This structure represents a single trace buffer record. */
> 60 struct t_rec {
> 61     uint64_t cycles;          /* cycle counter timestamp */
> 62     uint32_t event;           /* event ID                */
> 63     unsigned long data[5];    /* event data items        */
> 64 };
> 
> and defined a trace function in ./xen/common/trace.c
> 225 void trace(u32 event, unsigned long d1, unsigned long d2,
> 226            unsigned long d3, unsigned long d4, unsigned long d5)
> 227 {
> 
> But I still can''t understand what are these data real meaning
>  I never found a place in the source code where this function void
> trace(...) had been called.
Search for TRACE_ , there are macros that wrap the proper call to trace
based on the number of fields that the trace record is using.
> Can someone give me a clue about this?
> Or are those interfaces (d1...d5) for developers to define their own
> interest to track the event?
Let''s look at one of the trace macros:

xen/common/schedule.c:115

 TRACE_2D(TRC_SCHED_DOM_ADD, v->domain->domain_id, v->vcpu_id);

 The trace id is TRC_SCHED_DOM_ADD, is defined in 
 xen/include/public/trace.h, which is 

#define TRC_SCHED_DOM_ADD       (TRC_SCHED +  1)
 
#define TRC_SCHED   0x0002f000    /* Xen Scheduler trace      */

 so TRC_SCHED_DOM_ADD is 0x0002f0001

The _2D means the trace record expects to inputs.  The trace
infrastructure supports up to 5 parameters, TRACE_5D.

The xentrace formatter needs to know how to unpack the trace record, you
can look at  the unpacking in tools/xentrace/formats , looking at the
TRC_SCHED_DOM_ADD (0x0002f001), we can see it is unpacked as:

0x0002f001  CPU%(cpu)d  %(tsc)d     sched_add_domain  [ domid 0x%(1)08x, edomid
= 0x%(2)08x ]

-- 
Ryan Harper
Software Engineer; Linux Technology Center
IBM Corp., Austin, Tx
(512) 838-9253   T/L: 678-9253
ryanh@us.ibm.com

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel

Hi folks
Thanks very much ! I''ve got it.You guys'' direction and clue
are very clear!
And I''d like to talk  another topic about the xentrace tool.

xentrace tool is some kind of user space tool.
Based on xentrace source code (tools/xentrace/xentrace.c),it will get, map
and monitor the tracing data
from kernel space to the user space.I think xen use procfs to transfer data
from kernel space to uesr space.

Based on trace source code(xen/common/trace.c),dom0 tracing the event which
are enabled.
xen initialize tracing buffer for each cpu,trace buffer size (in pages) in
kenel space is defined by opt_tbuf_size.
The tracing buf use loop structure.

I guess when the tracing data increase rapidly ,and xentrace tool in user
space does not take them immediately.
Some tracing data will lost.Maybe relayfs or something else can solve this
problem.


On 6/12/06, Ryan Harper <ryanh@us.ibm.com> wrote:
>
> * rickey berkeley <rickey.berkeley@gmail.com> [2006-06-11 08:18]:
> > Hi folks:
>
> Search for TRACE_ , there are macros that wrap the proper call to trace
> based on the number of fields that the trace record is using.
>
> > Can someone give me a clue about this?
> > Or are those interfaces (d1...d5) for developers to define their own
> > interest to track the event?
>
> Let''s look at one of the trace macros:
>
> 0x0002f001  CPU%(cpu)d  %(tsc)d     sched_add_domain  [ domid >
0x%(1)08x, edomid = 0x%(2)08x ]
>
> --
> Ryan Harper
> Software Engineer; Linux Technology Center
> IBM Corp., Austin, Tx
> (512) 838-9253   T/L: 678-9253
> ryanh@us.ibm.com
>

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel

rickey berkeley wrote:
> Based on trace source code(xen/common/trace.c),dom0 tracing the event 
> which are enabled.
>
> xen initialize tracing buffer for each cpu,trace buffer size (in 
> pages) in kenel space is defined by opt_tbuf_size.
> The tracing buf use loop structure.
>
> I guess when the tracing data increase rapidly ,and xentrace tool in 
> user space does not take them immediately.
> Some tracing data will lost.Maybe relayfs or something else can solve 
> this problem.
>
I added a basic flow control mechanism to the trace buffer system a few 
months ago. You can see an example of how to use it in tools/xenmon. The 
way it works is that as trace records are generated, a software 
interrupt is generated when the trace buffer gets filled to a certain 
point. The user space tools can use select() on an event channel to find 
out about these interrupts. See tools/xenmon/xenbaked.c for exact 
programming details. This code has not been copied into xentrace yet; 
Feel free to do so yourself if you think it''s necessary.

Rob




_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel

Hi Rob,


On 6/14/06, Rob Gardner <rob.gardner@hp.com>
wrote:
> rickey berkeley wrote:
> > Based on trace source code(xen/common/trace.c),dom0 tracing the event
> > which are enabled.
> >
> > xen initialize tracing buffer for each cpu,trace buffer size (in
> > pages) in kenel space is defined by opt_tbuf_size.
> > The tracing buf use loop structure.
> >
> > I guess when the tracing data increase rapidly ,and xentrace tool in
> > user space does not take them immediately.
> > Some tracing data will lost.Maybe relayfs or something else can solve
> > this problem.
> >
>
> I added a basic flow control mechanism to the trace buffer system a few
> months ago. You can see an example of how to use it in tools/xenmon. The
> way it works is that as trace records are generated, a software
> interrupt is generated when the trace buffer gets filled to a certain
> point. The user space tools can use select() on an event channel to find
> out about these interrupts. See tools/xenmon/xenbaked.c for exact
> programming details. This code has not been copied into xentrace yet;
> Feel free to do so yourself if you think it''s necessary.
Would you explain a little bit more on how you handle the overflow? If
the userspace detects that event, what it does then?

Usually if there is no more space available in kernel buffer, what
will you do? Drop some data, and hope that the userspace will come up
to free some for more space in the future? Or if you don''t drop them,
just block there and wait for the userspace to come to free some?

I believe that there are few tactics for this problems, and what we
should do depends on situations.

Thanks.
H

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel

NAHieu wrote:
> On 6/14/06, Rob Gardner <rob.gardner@hp.com> wrote:
>> rickey berkeley wrote:
>> > Based on trace source code(xen/common/trace.c),dom0 tracing the
event
>> > which are enabled.
>> >
>> > xen initialize tracing buffer for each cpu,trace buffer size (in
>> > pages) in kenel space is defined by opt_tbuf_size.
>> > The tracing buf use loop structure.
>> >
>> > I guess when the tracing data increase rapidly ,and xentrace tool
in
>> > user space does not take them immediately.
>> > Some tracing data will lost.Maybe relayfs or something else can
solve
>> > this problem.
>> >
>>
>> I added a basic flow control mechanism to the trace buffer system a few
>> months ago. You can see an example of how to use it in tools/xenmon.
The
>> way it works is that as trace records are generated, a software
>> interrupt is generated when the trace buffer gets filled to a certain
>> point. The user space tools can use select() on an event channel to
find
>> out about these interrupts. See tools/xenmon/xenbaked.c for exact
>> programming details. This code has not been copied into xentrace yet;
>> Feel free to do so yourself if you think it''s necessary.
>
> Would you explain a little bit more on how you handle the overflow? If
> the userspace detects that event, what it does then?
If overflow occurs, it is not handled. The mechanism I implemented was 
just designed to drastically reduce the probability of overflow.

When xenbaked wakes up from its select() call (indicating the trace 
buffer high water mark has been reached) it simply starts reading trace 
records out of the trace buffers.
>
> Usually if there is no more space available in kernel buffer, what
> will you do? Drop some data, and hope that the userspace will come up
> to free some for more space in the future? Or if you don''t drop
them,
> just block there and wait for the userspace to come to free some?
Currently, the trace buffer "high water" mark is set to 50%. That is, 
when the hypervisor trace buffer becomes 1/2 full, it sends a soft 
interrupt to wake up xenbaked from its blocking select(). If nobody 
wakes up to read trace records from the trace buffer, I take that to 
mean that nobody cares about the trace records. When somebody does care, 
they will read those records in a timely manner. Obviously, the 
hypervisor cannot "block" if there is no room in the trace buffers; In
this case, new trace records simply overwrite old ones, and the old ones 
are lost.

If you encounter a situation where trace records are being generated too 
fast, and fill up the trace buffer too quickly, then the simple next 
step is to increase the size of the trace buffers. So far, use of the 
trace records has not been linked to anything so critical that it''s 
necessary to take extraordinary measures to avoid loss of data.

Rob





_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel