[Qemu-devel] RFC: Design Doc for a new trace format (to support variable number/size of args per event) simpletrace-v2

[Qemu-devel] RFC: Design Doc for a new trace format (to support variable number/size of args per event) simpletrace-v2

[Harsh Bora]

Currently, Qemu provides an in-built "simple" trace backend which is 
simple and easy to use (no additional/external dependencies) and allows 
developers to trace events in Qemu code, however, it suffers from 
limitations like unability to trace more than 6 elements per trace 
event, lack of string support, etc. There are various places in Qemu 
code, where one would want to trace events having multiple arguments 
including strings. This results into motivation for defining an 
advanced, yet simple trace format which will address these limitations. 
For the sake of convinence, let us call this new trace format as 
simpletrace v2 (any other better name?).

HLD for Simpletrace v2:
======================

This new trace format defines 3 types of structures for trace data 
organization:

1) Trace Log Header (per log file, provides meta-data about the entire 
trace log, like trace format version, endianness, etc.)
2) Trace Event Header (per trace event, provides meta-data per trace event)
3) Trace Data (per argument/data in a trace event, provides size of data 
followed by data itself)


  The Trace Log header can be defined like this:

typedef struct {
	uint64_t endian_magic; 	/* =0xAA0011FF, a magic number helps 
identifying validity and endian-ness of trace log to its readers */
	uint64_t pid; 		/* pid of qemu process can be traced here */
	uint64_t version; 	/* Keeping version info as 3rd 64-bit element as 
expected by current simpletrace format */
	unit64_t timestamp; 	/* timestamp info */
} TraceLogHeader;

Suggestions are invited to make this header more informative as required.

Further, this TraceLogHeader will be followed by 0 or more Trace Event 
Headers (further followed by trace data) as defined below:

typedef struct {
	uint64_t magic; 	/* =0xA1B2C3D4, ensures a valid trace record, 
otherwise corrupted */
	unit64_t id; 		/* unique identifer per trace event */
	uint64_t timestamp; 	/* timestamp info */
	uint64_t num_args; 	/* number of arguments (followed by this 
TraceEventHeader) traced in this trace event */
} TraceEventHeader;

Trace Data is expected to be stored in following format followed by 
TraceEventHeader:

typedef struct {
	uint64_t size; 	/* size of data in bytes to be read following this 
header */
	uint8_t data[0] /* variable sized data */
} TraceData;


So, a typical trace log would look like this:

	|TraceLogHeader|TraceEventHeader1|TraceData11|TraceData12|TraceEventHeader2|TraceData21| ...
...
...
... |TraceEventHeader-n|TraceData-n1|TraceData-n2|... TraceData-nm|

Programatically,

	typedef struct TraceEvent {
		TraceEventHeader eheader;
		TraceData edata[0];
	};

	typedef struct TraceLog {
		TraceLogHeader lheader;
		TraceEvent levents[0];
	};

I am planning to implement this new trace format soon and therefore 
would like to have suggestions/feedback at an early date if possible.

regards,
Harsh

Re: [Qemu-devel] RFC: Design Doc for a new trace format (to support variable number/size of args per event) simpletrace-v2

[Stefan Hajnoczi]

On Tue, Nov 29, 2011 at 8:29 AM, Harsh Bora <harsh@linux.vnet.ibm.com> wrote:
> Currently, Qemu provides an in-built "simple" trace backend which is simple
> and easy to use (no additional/external dependencies) and allows developers
> to trace events in Qemu code, however, it suffers from limitations like
> unability to trace more than 6 elements per trace event, lack of string
> support, etc. There are various places in Qemu code, where one would want to
> trace events having multiple arguments including strings. This results into
> motivation for defining an advanced, yet simple trace format which will
> address these limitations. For the sake of convinence, let us call this new
> trace format as simpletrace v2 (any other better name?).
>
> HLD for Simpletrace v2:
> ======================
>
> This new trace format defines 3 types of structures for trace data
> organization:
>
> 1) Trace Log Header (per log file, provides meta-data about the entire trace
> log, like trace format version, endianness, etc.)
> 2) Trace Event Header (per trace event, provides meta-data per trace event)
> 3) Trace Data (per argument/data in a trace event, provides size of data
> followed by data itself)
>
>
>  The Trace Log header can be defined like this:
>
> typedef struct {
>        uint64_t endian_magic;  /* =0xAA0011FF, a magic number helps
> identifying validity and endian-ness of trace log to its readers */
>        uint64_t pid;           /* pid of qemu process can be traced here */
>        uint64_t version;       /* Keeping version info as 3rd 64-bit element
> as expected by current simpletrace format */
>        unit64_t timestamp;     /* timestamp info */
> } TraceLogHeader;
>
> Suggestions are invited to make this header more informative as required.
>
> Further, this TraceLogHeader will be followed by 0 or more Trace Event
> Headers (further followed by trace data) as defined below:
>
> typedef struct {
>        uint64_t magic;         /* =0xA1B2C3D4, ensures a valid trace record,
> otherwise corrupted */
>        unit64_t id;            /* unique identifer per trace event */
>        uint64_t timestamp;     /* timestamp info */
>        uint64_t num_args;      /* number of arguments (followed by this
> TraceEventHeader) traced in this trace event */

What exactly is num_args?

> } TraceEventHeader;
>
> Trace Data is expected to be stored in following format followed by
> TraceEventHeader:
>
> typedef struct {
>        uint64_t size;  /* size of data in bytes to be read following this
> header */
>        uint8_t data[0] /* variable sized data */
> } TraceData;

This format does not support variable-length strings in a
self-describing way.  What I mean is that a trace record containing a
string should work in the simpletrace Python module:

class QMPAnalyzer(simpletrace.Analyzer):
    def handle_qmp_command(self, mon, cmd_name):
        print 'QMP command "%s" on monitor %#x' % (cmd_name, mon)

The cmd_name argument is a string and this script shows all QMP
commands that were handled.

A simple way of implementing this is to have simpletrace.py parse
trace-events and look for (const) char * arguments.  String arguments
are serialized like this:

uint16_t length;
char chars[length];

It may be useful to pad to the next 8-byte boundary after a string argument.

Stefan

Re: [Qemu-devel] RFC: Design Doc for a new trace format (to support variable number/size of args per event) simpletrace-v2

[Stefan Hajnoczi]

On Tue, Nov 29, 2011 at 11:34 AM, Stefan Hajnoczi <stefanha@gmail.com> wrote:
> On Tue, Nov 29, 2011 at 8:29 AM, Harsh Bora <harsh@linux.vnet.ibm.com> wrote:
>> Currently, Qemu provides an in-built "simple" trace backend which is simple
>> and easy to use (no additional/external dependencies) and allows developers
>> to trace events in Qemu code, however, it suffers from limitations like
>> unability to trace more than 6 elements per trace event, lack of string
>> support, etc. There are various places in Qemu code, where one would want to
>> trace events having multiple arguments including strings. This results into
>> motivation for defining an advanced, yet simple trace format which will
>> address these limitations. For the sake of convinence, let us call this new
>> trace format as simpletrace v2 (any other better name?).
>>
>> HLD for Simpletrace v2:
>> ======================
>>
>> This new trace format defines 3 types of structures for trace data
>> organization:
>>
>> 1) Trace Log Header (per log file, provides meta-data about the entire trace
>> log, like trace format version, endianness, etc.)
>> 2) Trace Event Header (per trace event, provides meta-data per trace event)
>> 3) Trace Data (per argument/data in a trace event, provides size of data
>> followed by data itself)
>>
>>
>>  The Trace Log header can be defined like this:
>>
>> typedef struct {
>>        uint64_t endian_magic;  /* =0xAA0011FF, a magic number helps
>> identifying validity and endian-ness of trace log to its readers */
>>        uint64_t pid;           /* pid of qemu process can be traced here */
>>        uint64_t version;       /* Keeping version info as 3rd 64-bit element
>> as expected by current simpletrace format */
>>        unit64_t timestamp;     /* timestamp info */
>> } TraceLogHeader;
>>
>> Suggestions are invited to make this header more informative as required.
>>
>> Further, this TraceLogHeader will be followed by 0 or more Trace Event
>> Headers (further followed by trace data) as defined below:
>>
>> typedef struct {
>>        uint64_t magic;         /* =0xA1B2C3D4, ensures a valid trace record,
>> otherwise corrupted */
>>        unit64_t id;            /* unique identifer per trace event */
>>        uint64_t timestamp;     /* timestamp info */
>>        uint64_t num_args;      /* number of arguments (followed by this
>> TraceEventHeader) traced in this trace event */
>
> What exactly is num_args?
>
>> } TraceEventHeader;
>>
>> Trace Data is expected to be stored in following format followed by
>> TraceEventHeader:
>>
>> typedef struct {
>>        uint64_t size;  /* size of data in bytes to be read following this
>> header */
>>        uint8_t data[0] /* variable sized data */
>> } TraceData;
>
> This format does not support variable-length strings in a
> self-describing way.

I used the word "self-describing".  To be clear I think we should not
put any trace event metadata into the trace file.  Instead we continue
to rely on having the trace-events file together with the trace file.

This keeps the trace format simple.  If we do want a self-describing
trace format then I think we should use the Common Trace Format that
LTTng is working on instead of rolling our own.

So forget I said "self-describing" :).  I think the only changes from
the v1 format we need are:

1. New magic number to mark v2 format.

2. Trace records are no longer fixed-length, they include a size field:

typedef struct {
    uint32_t length; /* in bytes */
    uint32_t reserved; /* unused */
    uint64_t event;
    uint64_t timestamp_ns;
    uint8_t arguments[];
} TraceRecord;

3. Strings are serialized like this:

uint16_t length;
char chars[length];

These changes enable:

1. Variable number of trace event arguments.

2. Variable-length strings.

Stefan

Re: [Qemu-devel] RFC: Design Doc for a new trace format (to support variable number/size of args per event) simpletrace-v2

[Markus Armbruster]

Stefan Hajnoczi <stefanha@gmail.com> writes:

[...]
> So forget I said "self-describing" :).  I think the only changes from
> the v1 format we need are:
>
> 1. New magic number to mark v2 format.
>
> 2. Trace records are no longer fixed-length, they include a size field:
>
> typedef struct {
>     uint32_t length; /* in bytes */
>     uint32_t reserved; /* unused */
>     uint64_t event;
>     uint64_t timestamp_ns;
>     uint8_t arguments[];
> } TraceRecord;
>
> 3. Strings are serialized like this:
>
> uint16_t length;
> char chars[length];

16 bit length?  Sure you want that?

> These changes enable:
>
> 1. Variable number of trace event arguments.
>
> 2. Variable-length strings.

Byte strings, i.e. zero bytes not special.

Re: [Qemu-devel] RFC: Design Doc for a new trace format (to support variable number/size of args per event) simpletrace-v2

[Stefan Hajnoczi]

On Tue, Nov 29, 2011 at 12:35 PM, Markus Armbruster <armbru@redhat.com> wrote:
> Stefan Hajnoczi <stefanha@gmail.com> writes:
>
> [...]
>> So forget I said "self-describing" :).  I think the only changes from
>> the v1 format we need are:
>>
>> 1. New magic number to mark v2 format.
>>
>> 2. Trace records are no longer fixed-length, they include a size field:
>>
>> typedef struct {
>>     uint32_t length; /* in bytes */
>>     uint32_t reserved; /* unused */
>>     uint64_t event;
>>     uint64_t timestamp_ns;
>>     uint8_t arguments[];
>> } TraceRecord;
>>
>> 3. Strings are serialized like this:
>>
>> uint16_t length;
>> char chars[length];
>
> 16 bit length?  Sure you want that?

You're right, it's more future-proof to use a larger type.  Since I
said uint32_t length in TraceRecord, uint32_t here would work well.

Stefan

Re: [Qemu-devel] RFC: Design Doc for a new trace format (to support variable number/size of args per event) simpletrace-v2

[Harsh Bora]

On 11/29/2011 06:26 PM, Stefan Hajnoczi wrote:
> On Tue, Nov 29, 2011 at 12:35 PM, Markus Armbruster<armbru@redhat.com>  wrote:
>> Stefan Hajnoczi<stefanha@gmail.com>  writes:
>>
>> [...]
>>> So forget I said "self-describing" :).  I think the only changes from
>>> the v1 format we need are:
>>>
>>> 1. New magic number to mark v2 format.
>>>
>>> 2. Trace records are no longer fixed-length, they include a size field:
>>>
>>> typedef struct {
>>>      uint32_t length; /* in bytes */
>>>      uint32_t reserved; /* unused */
>>>      uint64_t event;
>>>      uint64_t timestamp_ns;
>>>      uint8_t arguments[];
>>> } TraceRecord;
>>>
>>> 3. Strings are serialized like this:
>>>
>>> uint16_t length;
>>> char chars[length];
>>
>> 16 bit length?  Sure you want that?
>
> You're right, it's more future-proof to use a larger type.  Since I
> said uint32_t length in TraceRecord, uint32_t here would work well.

Makes sense to store size info only for strings as long as we rely on 
trace-events file to identify other meta-data about trace-events.

thanks,
Harsh

>
> Stefan
>