Question about xentrace to trace s_time_t type of data

Question about xentrace to trace s_time_t type of data

[Meng Xu]

[-- Attachment #1.1: Type: text/plain, Size: 2498 bytes --]

Hi,

I'm trying to trace the scheduler-specific events for debug purpose by
using xentrace (instead of using printk). I read the trace code in credit
and credit2 scheduler (sched_credit.c and sched_credit2.c) and "followed"
the way credit2 wrote.

I added the following code into the burn_budget() in my scheduler file,
sched_rt.c:

        /* TRACE */

        {

            struct {

                unsigned dom:16,vcpu:16;

                s_time_t cur_budget;

            } d;

            d.dom = svc->vcpu->domain->domain_id;

            d.vcpu = svc->vcpu->vcpu_id;

            d.cur_budget = svc->cur_budget;

            trace_var(TRC_RT_BUDGET_REPLENISH, 1,

                      sizeof(d),

                      (unsigned char *) &d);

        }

​The result I got from "xenanalyze --dump-all"​ for this event is (I only
show one entry):

]  0.285656366 x-|- d0v1   22804(2:2:804) 4 [ 00010000 ffff82d0 003d0900
00000000 ]

​What I'm confused is the meaning of "[ 00010000 ffff82d0 003d0900 00000000
]":

I can understand that 00010000 represents dom 0's vcpu 1. But I don't know
how to interpret the rest of numbers "ffff82d0 003d0900 00000000".

The cur_budget traced should always be 4000000. So the expected result
should be the hex value of 4000000.

*My question is:*
1) How should I interpret the    "ffff82d0 003d0900 00000000 " to be
"4000000"?
2) Why does it has three more 32bits in "[ 00010000 ffff82d0 003d0900
00000000 ]" instead of just two? (since s_time_t is a signed 64 bit type)

It seems that xentrace just dump this struct d to a file and xenalyze just
print it out one by one (and each item is 32bit). In my opinion, the output
in [ ... ]​ should have only three 32bit-size fields instead of 4. I'm not
sure where it goes wrong.

I also tried to change the struct d to

 struct {

                unsigned dom:16,vcpu:16;

                unsigned cur_budget_lo;

                unsigned cur_budget_hi;

            } d;
​and it give me expected output, which has only three 32bit-size fields in
[ ... ] in  xenalyze's output​.

So I'm guessing I should not use a field larger than 32bit in the trace
struct d. But I'm not sure about the reason. Could any one give me some
insight?

Thank you very much for your time and help in this question!

Best,

Meng


-----------
Meng Xu
PhD Student in Computer and Information Science
University of Pennsylvania

[-- Attachment #1.2: Type: text/html, Size: 5228 bytes --]

[-- Attachment #2: Type: text/plain, Size: 126 bytes --]

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

Re: Question about xentrace to trace s_time_t type of data

[Konrad Rzeszutek Wilk]

On Sat, Aug 23, 2014 at 11:24:21PM -0400, Meng Xu wrote:
> Hi,
> 
> I'm trying to trace the scheduler-specific events for debug purpose by
> using xentrace (instead of using printk). I read the trace code in credit
> and credit2 scheduler (sched_credit.c and sched_credit2.c) and "followed"
> the way credit2 wrote.
> 
> I added the following code into the burn_budget() in my scheduler file,
> sched_rt.c:
> 
>         /* TRACE */
> 
>         {
> 
>             struct {
> 
>                 unsigned dom:16,vcpu:16;
> 
>                 s_time_t cur_budget;
> 
>             } d;
> 
>             d.dom = svc->vcpu->domain->domain_id;
> 
>             d.vcpu = svc->vcpu->vcpu_id;
> 
>             d.cur_budget = svc->cur_budget;
> 
>             trace_var(TRC_RT_BUDGET_REPLENISH, 1,
> 
>                       sizeof(d),
> 
>                       (unsigned char *) &d);

You put the virtual address addresss of your 'd' structure
that is on the stack in the trace file. That does not contain any
data except an address.

What you need to do is to put the data as such:

	uint32_t dom_vcpu;

	dom_vcpu = srv->vcpu->domain->domain_id;
	dom_vcpu |= (svc->vcpu->vcpu_id << 16);
	TRACE_2D(TRC_RT_BUDGET_REPLENISH, dom_vcpu, svc->cur_budget);

> 
>         }
> 
> ​The result I got from "xenanalyze --dump-all"​ for this event is (I only
> show one entry):
> 
> ]  0.285656366 x-|- d0v1   22804(2:2:804) 4 [ 00010000 ffff82d0 003d0900
> 00000000 ]
> 
> ​What I'm confused is the meaning of "[ 00010000 ffff82d0 003d0900 00000000
> ]":
> 
> I can understand that 00010000 represents dom 0's vcpu 1. But I don't know
> how to interpret the rest of numbers "ffff82d0 003d0900 00000000".

It is a virtual address.
> 
> The cur_budget traced should always be 4000000. So the expected result
> should be the hex value of 4000000.
> 
> *My question is:*
> 1) How should I interpret the    "ffff82d0 003d0900 00000000 " to be
> "4000000"?
> 2) Why does it has three more 32bits in "[ 00010000 ffff82d0 003d0900
> 00000000 ]" instead of just two? (since s_time_t is a signed 64 bit type)
> 
> It seems that xentrace just dump this struct d to a file and xenalyze just
> print it out one by one (and each item is 32bit). In my opinion, the output
> in [ ... ]​ should have only three 32bit-size fields instead of 4. I'm not
> sure where it goes wrong.
> 
> I also tried to change the struct d to
> 
>  struct {
> 
>                 unsigned dom:16,vcpu:16;
> 
>                 unsigned cur_budget_lo;
> 
>                 unsigned cur_budget_hi;
> 
>             } d;
> ​and it give me expected output, which has only three 32bit-size fields in
> [ ... ] in  xenalyze's output​.
> 
> So I'm guessing I should not use a field larger than 32bit in the trace
> struct d. But I'm not sure about the reason. Could any one give me some
> insight?
> 
> Thank you very much for your time and help in this question!
> 
> Best,
> 
> Meng
> 
> 
> -----------
> Meng Xu
> PhD Student in Computer and Information Science
> University of Pennsylvania

> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel


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

Re: Question about xentrace to trace s_time_t type of data

[Meng Xu]

[-- Attachment #1.1: Type: text/plain, Size: 3527 bytes --]

Hi Konrad,

Thank you very much for answering my question!

​I actually have a question regarding to your answer.

Briefly speaking, I'm thinking what you suggests is doing the same (or
similar) thing as I did? Below is my reason.


> >
> > I'm trying to trace the scheduler-specific events for debug purpose by
> > using xentrace (instead of using printk). I read the trace code in credit
> > and credit2 scheduler (sched_credit.c and sched_credit2.c) and "followed"
> > the way credit2 wrote.
> >
> > I added the following code into the burn_budget() in my scheduler file,
> > sched_rt.c:
> >
> >         /* TRACE */
> >
> >         {
> >
> >             struct {
> >
> >                 unsigned dom:16,vcpu:16;
> >
> >                 s_time_t cur_budget;
> >
> >             } d;
> >
> >             d.dom = svc->vcpu->domain->domain_id;
> >
> >             d.vcpu = svc->vcpu->vcpu_id;
> >
> >             d.cur_budget = svc->cur_budget;
> >
> >             trace_var(TRC_RT_BUDGET_REPLENISH, 1,
> >
> >                       sizeof(d),
> >
> >                       (unsigned char *) &d);
>
> You put the virtual address addresss of your 'd' structure
> that is on the stack in the trace file. That does not contain any
> data except an address.
>
> What you need to do is to put the data as such:
>
>         uint32_t dom_vcpu;
>
>         dom_vcpu = srv->vcpu->domain->domain_id;
>         dom_vcpu |= (svc->vcpu->vcpu_id << 16);
>         TRACE_2D(TRC_RT_BUDGET_REPLENISH, dom_vcpu, svc->cur_budget);
>

​In file xen/include/xen/trace.h, TRACE_2D is defined as follows:

#define TRACE_2D(_e,d1,d2)                                      \

    do {                                                        \

        if ( unlikely(tb_init_done) )                           \

        {                                                       \

            u32 _d[2];                                          \

            _d[0] = d1;                                         \

            _d[1] = d2;                                         \

            __trace_var(_e, 1, sizeof(_d), _d);                 \

        }                                                       \
    } while ( 0 )​



​In the same file, the trace_var() is defined as follows:

static inline void trace_var(u32 event, int cycles, int extra,

                             const void *extra_data)

{

    if ( unlikely(tb_init_done) )

        __trace_var(event, cycles, extra, extra_data);
}   ​

​
The description of the function __trace_var(u32 event, bool_t cycles,
unsigned int extra,const void *extra_data) is in xen/common/trace.c:

/**

 * __trace_var - Enters a trace tuple into the trace buffer for the current
CPU.

 * @event: the event type being logged

 * @cycles: include tsc timestamp into trace record

 * @extra: size of additional trace data in bytes

 * @extra_data: pointer to additional trace data

 *

 * Logs a trace record into the appropriate buffer.
 */​


So I'm thinking what you suggests is doing the same (or similar) thing as I
did? In addition, from the description of the function __trace_var() , it
seems I should parse the pointer of the struct d to this function.

​Maybe I misunderstood your suggestion?

Thank you very much for your time!

Best,

Meng​




-----------
Meng Xu
PhD Student in Computer and Information Science
University of Pennsylvania

[-- Attachment #1.2: Type: text/html, Size: 6774 bytes --]

[-- Attachment #2: Type: text/plain, Size: 126 bytes --]

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

Re: Question about xentrace to trace s_time_t type of data

[Konrad Rzeszutek Wilk]

On Mon, Aug 25, 2014 at 11:14:52AM -0400, Meng Xu wrote:
> Hi Konrad,
> 
> Thank you very much for answering my question!
> 
> ​I actually have a question regarding to your answer.
> 
> Briefly speaking, I'm thinking what you suggests is doing the same (or
> similar) thing as I did? Below is my reason.
> 
> 
> > >
> > > I'm trying to trace the scheduler-specific events for debug purpose by
> > > using xentrace (instead of using printk). I read the trace code in credit
> > > and credit2 scheduler (sched_credit.c and sched_credit2.c) and "followed"
> > > the way credit2 wrote.
> > >
> > > I added the following code into the burn_budget() in my scheduler file,
> > > sched_rt.c:
> > >
> > >         /* TRACE */
> > >
> > >         {
> > >
> > >             struct {
> > >
> > >                 unsigned dom:16,vcpu:16;
> > >
> > >                 s_time_t cur_budget;
> > >
> > >             } d;
> > >
> > >             d.dom = svc->vcpu->domain->domain_id;
> > >
> > >             d.vcpu = svc->vcpu->vcpu_id;
> > >
> > >             d.cur_budget = svc->cur_budget;
> > >
> > >             trace_var(TRC_RT_BUDGET_REPLENISH, 1,
> > >
> > >                       sizeof(d),
> > >
> > >                       (unsigned char *) &d);
> >
> > You put the virtual address addresss of your 'd' structure
> > that is on the stack in the trace file. That does not contain any
> > data except an address.
> >
> > What you need to do is to put the data as such:
> >
> >         uint32_t dom_vcpu;
> >
> >         dom_vcpu = srv->vcpu->domain->domain_id;
> >         dom_vcpu |= (svc->vcpu->vcpu_id << 16);
> >         TRACE_2D(TRC_RT_BUDGET_REPLENISH, dom_vcpu, svc->cur_budget);
> >
> 
> ​In file xen/include/xen/trace.h, TRACE_2D is defined as follows:
> 
> #define TRACE_2D(_e,d1,d2)                                      \
> 
>     do {                                                        \
> 
>         if ( unlikely(tb_init_done) )                           \
> 
>         {                                                       \
> 
>             u32 _d[2];                                          \
> 
>             _d[0] = d1;                                         \
> 
>             _d[1] = d2;                                         \
> 
>             __trace_var(_e, 1, sizeof(_d), _d);                 \
> 
>         }                                                       \
>     } while ( 0 )​
> 
> 
> 
> ​In the same file, the trace_var() is defined as follows:
> 
> static inline void trace_var(u32 event, int cycles, int extra,
> 
>                              const void *extra_data)
> 
> {
> 
>     if ( unlikely(tb_init_done) )
> 
>         __trace_var(event, cycles, extra, extra_data);
> }   ​
> 
> ​
> The description of the function __trace_var(u32 event, bool_t cycles,
> unsigned int extra,const void *extra_data) is in xen/common/trace.c:
> 
> /**
> 
>  * __trace_var - Enters a trace tuple into the trace buffer for the current
> CPU.
> 
>  * @event: the event type being logged
> 
>  * @cycles: include tsc timestamp into trace record
> 
>  * @extra: size of additional trace data in bytes
> 
>  * @extra_data: pointer to additional trace data
> 
>  *
> 
>  * Logs a trace record into the appropriate buffer.
>  */​
> 
> 
> So I'm thinking what you suggests is doing the same (or similar) thing as I
> did? In addition, from the description of the function __trace_var() , it
> seems I should parse the pointer of the struct d to this function.
> 
> ​Maybe I misunderstood your suggestion?
> 
> Thank you very much for your time!

I have to be honest I hadn't actually dug in what was underneath
the macro. Just been using the macro and it had worked for me.


> 
> Best,
> 
> Meng​
> 
> 
> 
> 
> -----------
> Meng Xu
> PhD Student in Computer and Information Science
> University of Pennsylvania

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

Re: Question about xentrace to trace s_time_t type of data

[Meng Xu]

[-- Attachment #1.1: Type: text/plain, Size: 4625 bytes --]

Hi Konrad,



2014-08-25 11:20 GMT-04:00 Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>:

> On Mon, Aug 25, 2014 at 11:14:52AM -0400, Meng Xu wrote:
> > Hi Konrad,
> >
> > Thank you very much for answering my question!
> >
> > ​I actually have a question regarding to your answer.
> >
> > Briefly speaking, I'm thinking what you suggests is doing the same (or
> > similar) thing as I did? Below is my reason.
> >
> >
> > > >
> > > > I'm trying to trace the scheduler-specific events for debug purpose
> by
> > > > using xentrace (instead of using printk). I read the trace code in
> credit
> > > > and credit2 scheduler (sched_credit.c and sched_credit2.c) and
> "followed"
> > > > the way credit2 wrote.
> > > >
> > > > I added the following code into the burn_budget() in my scheduler
> file,
> > > > sched_rt.c:
> > > >
> > > >         /* TRACE */
> > > >
> > > >         {
> > > >
> > > >             struct {
> > > >
> > > >                 unsigned dom:16,vcpu:16;
> > > >
> > > >                 s_time_t cur_budget;
> > > >
> > > >             } d;
> > > >
> > > >             d.dom = svc->vcpu->domain->domain_id;
> > > >
> > > >             d.vcpu = svc->vcpu->vcpu_id;
> > > >
> > > >             d.cur_budget = svc->cur_budget;
> > > >
> > > >             trace_var(TRC_RT_BUDGET_REPLENISH, 1,
> > > >
> > > >                       sizeof(d),
> > > >
> > > >                       (unsigned char *) &d);
> > >
> > > You put the virtual address addresss of your 'd' structure
> > > that is on the stack in the trace file. That does not contain any
> > > data except an address.
> > >
> > > What you need to do is to put the data as such:
> > >
> > >         uint32_t dom_vcpu;
> > >
> > >         dom_vcpu = srv->vcpu->domain->domain_id;
> > >         dom_vcpu |= (svc->vcpu->vcpu_id << 16);
> > >         TRACE_2D(TRC_RT_BUDGET_REPLENISH, dom_vcpu, svc->cur_budget);
> > >
> >
> > ​In file xen/include/xen/trace.h, TRACE_2D is defined as follows:
> >
> > #define TRACE_2D(_e,d1,d2)                                      \
> >
> >     do {                                                        \
> >
> >         if ( unlikely(tb_init_done) )                           \
> >
> >         {                                                       \
> >
> >             u32 _d[2];                                          \
> >
> >             _d[0] = d1;                                         \
> >
> >             _d[1] = d2;                                         \
> >
> >             __trace_var(_e, 1, sizeof(_d), _d);                 \
> >
> >         }                                                       \
> >     } while ( 0 )​
> >
> >
> >
> > ​In the same file, the trace_var() is defined as follows:
> >
> > static inline void trace_var(u32 event, int cycles, int extra,
> >
> >                              const void *extra_data)
> >
> > {
> >
> >     if ( unlikely(tb_init_done) )
> >
> >         __trace_var(event, cycles, extra, extra_data);
> > }   ​
> >
> > ​
> > The description of the function __trace_var(u32 event, bool_t cycles,
> > unsigned int extra,const void *extra_data) is in xen/common/trace.c:
> >
> > /**
> >
> >  * __trace_var - Enters a trace tuple into the trace buffer for the
> current
> > CPU.
> >
> >  * @event: the event type being logged
> >
> >  * @cycles: include tsc timestamp into trace record
> >
> >  * @extra: size of additional trace data in bytes
> >
> >  * @extra_data: pointer to additional trace data
> >
> >  *
> >
> >  * Logs a trace record into the appropriate buffer.
> >  */​
> >
> >
> > So I'm thinking what you suggests is doing the same (or similar) thing
> as I
> > did? In addition, from the description of the function __trace_var() , it
> > seems I should parse the pointer of the struct d to this function.
> >
> > ​Maybe I misunderstood your suggestion?
> >
> > Thank you very much for your time!
>
> I have to be honest I hadn't actually dug in what was underneath
> the macro. Just been using the macro and it had worked for me.
>
>
​Thank you for your time, anyway! :-)

I think the issue is when I tried to trace a type of data larger than
32bits, such as the type s_time_t, the trace_var() result  becomes
uninterpretable. Maybe I should never simply pass a type of data larger
than 32bit to trace macro, but  I don't know (and I hope to know) why.  :-(

​Best,

Meng​

-----------
Meng Xu
PhD Student in Computer and Information Science
University of Pennsylvania

[-- Attachment #1.2: Type: text/html, Size: 6780 bytes --]

[-- Attachment #2: Type: text/plain, Size: 126 bytes --]

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

Re: Question about xentrace to trace s_time_t type of data

[Konrad Rzeszutek Wilk]

. snip..
> > > Thank you very much for your time!
> >
> > I have to be honest I hadn't actually dug in what was underneath
> > the macro. Just been using the macro and it had worked for me.
> >
> >
> ​Thank you for your time, anyway! :-)
> 
> I think the issue is when I tried to trace a type of data larger than
> 32bits, such as the type s_time_t, the trace_var() result  becomes
> uninterpretable. Maybe I should never simply pass a type of data larger
> than 32bit to trace macro, but  I don't know (and I hope to know) why.  :-(

Oh, probably because of not packing. I would split all your
data types to be within a 32-bit unsigned int member. You can use
bit shiffting to pack data.

I presume the macros "fix" this for me as they will warn me when I try
to use an 64-bit value and I've had always to play the << game to "fit"
an 64-bit value in (by using two 32-bit arguments).
> 
> ​Best,
> 
> Meng​
> 
> -----------
> Meng Xu
> PhD Student in Computer and Information Science
> University of Pennsylvania

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

Re: Question about xentrace to trace s_time_t type of data

[Meng Xu]

[-- Attachment #1.1: Type: text/plain, Size: 1369 bytes --]

Hi Konrad,

2014-08-25 12:39 GMT-04:00 Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>:

> . snip..
> > > > Thank you very much for your time!
> > >
> > > I have to be honest I hadn't actually dug in what was underneath
> > > the macro. Just been using the macro and it had worked for me.
> > >
> > >
> > ​Thank you for your time, anyway! :-)
> >
> > I think the issue is when I tried to trace a type of data larger than
> > 32bits, such as the type s_time_t, the trace_var() result  becomes
> > uninterpretable. Maybe I should never simply pass a type of data larger
> > than 32bit to trace macro, but  I don't know (and I hope to know) why.
> :-(
>
> Oh, probably because of not packing. I would split all your
> data types to be within a 32-bit unsigned int member. You can use
> bit shiffting to pack data.
>
> I presume the macros "fix" this for me as they will warn me when I try
> to use an 64-bit value and I've had always to play the << game to "fit"
> an 64-bit value in (by using two 32-bit arguments).
>

​I see.  I did use the bit shifting to pack a 64bit data to two 32bit
unsigned int in my previous rt scheduler patch.

Thank you very much for confirming the workable approach! :-P​

Best,

​Meng​

-- 


-----------
Meng Xu
PhD Student in Computer and Information Science
University of Pennsylvania

[-- Attachment #1.2: Type: text/html, Size: 2270 bytes --]

[-- Attachment #2: Type: text/plain, Size: 126 bytes --]

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

Re: Question about xentrace to trace s_time_t type of data

[George Dunlap]

On 08/25/2014 02:31 PM, Konrad Rzeszutek Wilk wrote:
> On Sat, Aug 23, 2014 at 11:24:21PM -0400, Meng Xu wrote:
>> Hi,
>>
>> I'm trying to trace the scheduler-specific events for debug purpose by
>> using xentrace (instead of using printk). I read the trace code in credit
>> and credit2 scheduler (sched_credit.c and sched_credit2.c) and "followed"
>> the way credit2 wrote.
>>
>> I added the following code into the burn_budget() in my scheduler file,
>> sched_rt.c:
>>
>>          /* TRACE */
>>
>>          {
>>
>>              struct {
>>
>>                  unsigned dom:16,vcpu:16;
>>
>>                  s_time_t cur_budget;
>>
>>              } d;
>>
>>              d.dom = svc->vcpu->domain->domain_id;
>>
>>              d.vcpu = svc->vcpu->vcpu_id;
>>
>>              d.cur_budget = svc->cur_budget;
>>
>>              trace_var(TRC_RT_BUDGET_REPLENISH, 1,
>>
>>                        sizeof(d),
>>
>>                        (unsigned char *) &d);
> You put the virtual address addresss of your 'd' structure
> that is on the stack in the trace file. That does not contain any
> data except an address.

No; trace_var() takes a pointer to a struct and a size.  Meng is 
following the example he's seen in sched_credit2.c. :-)

The size of the structure is larger because the structure isn't 
"packed": by default it will try to make 64-bit elements 64-bit aligned 
by adding in "padding".  You can get around this in one of two ways:

1. Re-arranging the elements so they're naturally aligned.  In this 
case, you could do
struct {
     s_time_t cur_budget;
     unsigned dom:16, vcpu:16;
} d;

2. Adding "__packed" after "struct".  This tells the compiler not to try 
to align the bytes according to their size.

That explains why it's 4 words instead of 3, but I'm still a bit 
mistified why it's not something like
  [ 00010000 <garbage> 40000000 00000000 ]

I guess try with a packed structure and see what you get. :-)

  -George