how to avoid lost trace records?

how to avoid lost trace records?

[Olaf Hering]

Today I inspected the xenalyze and the dump-raw output and noticed that
huge number of lost trace records, even when booted with tbuf_size=200:

grep -wn 1f001 log.sles11_6.xentrace.txt.dump-raw
274438:R p 5 o000000000063ffd4    1f001 4 t0000006d215b3c6b [ b6aed 57fff 9e668fb6 51 ]
274468:R p 3 o00000000006401e8    1f001 4 t0000006e21a1c004 [ b557d 37fff 87924040 51 ]
274554:R p 2 o0000000000640668    1f001 4 t0000006e62629592 [ c7747 40000 b8f5d7ac 4f ]
274562:R p 0 o00000000006406dc    1f001 4 t0000006e63e3415a [ be911 7fff fb77cb80 4a ]
274567:R p 1 o0000000000640728    1f001 4 t0000006e6e45e5d5 [ e624e 0 199d7db0 4b ]
321539:R p 1 o0000000000726128    1f001 4 t0000006e76da7821 [ 2554 0 756c584b 6e ]
329858:R p 1 o000000000074eba8    1f001 4 t0000006e95de2638 [ 289b7 0 781c474a 6e ]
348457:R p 1 o00000000008042a0    1f001 4 t0000006e9c0cea86 [ 15202 0 96ff6f1e 6e ]
352634:R p 7 o000000000082ca74    1f001 4 t0000006ed46cea24 [ b18f0 40000 9efcab44 51 ]
354038:R p 4 o0000000000837df0    1f001 4 t0000006fe86a765f [ c402e 1 86b51960 51 ]
356635:R p 6 o00000000008474e0    1f001 4 t0000007671b75052 [ b69dd 1 9e4272a2 51 ]
356716:R p 1 o0000000000847b80    1f001 4 t000000769dc250ca [ 21f5f 1 9c526d83 6e ]

That means more than 740K lost entries on cpu5,3,2,1,0.
Is this expected?
This is 4.0 with a simple boot into Linux and shut it down again.

My command line was first just '-e all', now its like this and it does
not really reduce the number of lost entries:
xentrace -s 1 -e $(( 0x0010f000 | 0x0001f000 + 1 | 0x0001f000 + 2 | 0x0001f000 + 3 )) $file

Is the tracebuffer handling well debugged?

Olaf

Re: how to avoid lost trace records?

[Olaf Hering]

On Fri, Nov 19, Olaf Hering wrote:

> Today I inspected the xenalyze and the dump-raw output and noticed that
> huge number of lost trace records, even when booted with tbuf_size=200:

Adding some silly debug to insert_lost_records() to record the count of
the individual lost events shows lots of hypercall and stuff.
However, its odd that 20f101 gets past the 10f000 tb_event_mask in
__trace_var().

                 array index, cpu, event, number
(XEN) tb_control tb_event_mask 10f000
(XEN) trace.c:256:d0 tb_set_size from 239 to 20 not implemented
(XEN) insert_lost_records #0 c 2 e 20f101 n 7545b
(XEN) insert_lost_records #1 c 2 e 20f104 n 22de8
(XEN) insert_lost_records #2 c 2 e 21211 n 169e
(XEN) insert_lost_records #3 c 2 e 28004 n 16f2
(XEN) insert_lost_records #4 c 2 e 28006 n 183a
(XEN) insert_lost_records #5 c 2 e 2800e n 2fdb
(XEN) insert_lost_records #6 c 2 e 2800f n 2fdb
(XEN) insert_lost_records #7 c 2 e 2800a n 2fdb
(XEN) insert_lost_records #8 c 2 e 21021 n 17f2
(XEN) insert_lost_records #9 c 2 e 21101 n 2fdb
(XEN) insert_lost_records #10 c 2 e 21011 n 17df
(XEN) insert_lost_records #11 c 2 e 20f008 n ce
(XEN) insert_lost_records #12 c 2 e 20f103 n 717
(XEN) insert_lost_records #13 c 2 e 20f10b n 1145
(XEN) insert_lost_records #14 c 2 e 20f106 n 16f
(XEN) insert_lost_records #15 c 2 e 21002 n 97
(XEN) insert_lost_records #16 c 2 e 801001 n 5a
(XEN) insert_lost_records #17 c 2 e 802001 n 21b4
(XEN) insert_lost_records #18 c 2 e 802002 n 21b3
(XEN) insert_lost_records #19 c 2 e 21031 n a
(XEN) insert_lost_records #20 c 2 e 21311 n a
(XEN) insert_lost_records #21 c 2 e 1f004 n 1
(XEN) insert_lost_records #22 c 2 e 10f005 n 800
(XEN) insert_lost_records #23 c 2 e 10f03b n 800
(XEN) cpupool_add_domain(dom=1,pool=0) n_dom 2
(XEN) insert_lost_records #0 c 3 e 20f101 n 7c4df
(XEN) insert_lost_records #1 c 3 e 20f104 n 219b6
(XEN) insert_lost_records #2 c 3 e 20f103 n b28
(XEN) insert_lost_records #3 c 3 e 28006 n 1a31
(XEN) insert_lost_records #4 c 3 e 2800e n 33e2
(XEN) insert_lost_records #5 c 3 e 2800f n 33e2
(XEN) insert_lost_records #6 c 3 e 2800a n 33e2
(XEN) insert_lost_records #7 c 3 e 21021 n 19db
(XEN) insert_lost_records #8 c 3 e 21101 n 33e2
(XEN) insert_lost_records #9 c 3 e 802001 n 29db
(XEN) insert_lost_records #10 c 3 e 802002 n 29da
(XEN) insert_lost_records #11 c 3 e 21011 n 19f9
(XEN) insert_lost_records #12 c 3 e 21211 n 1b99
(XEN) insert_lost_records #13 c 3 e 28004 n 1de4
(XEN) insert_lost_records #14 c 3 e 20f008 n f3
(XEN) insert_lost_records #15 c 3 e 801001 n 53
(XEN) insert_lost_records #16 c 3 e 20f10b n 10d7
(XEN) insert_lost_records #17 c 3 e 21002 n ad
(XEN) insert_lost_records #18 c 3 e 21031 n e
(XEN) insert_lost_records #19 c 3 e 21311 n e
(XEN) insert_lost_records #20 c 3 e 20f106 n 28c
(XEN) insert_lost_records #21 c 3 e 1f004 n 529
(XEN) insert_lost_records #0 c 3 e 10f005 n 1c7a6
(XEN) insert_lost_records #1 c 3 e 10f03b n f1
(XEN) insert_lost_records #0 c 5 e 20f101 n 7134e
(XEN) insert_lost_records #1 c 5 e 20f104 n 23dc3
(XEN) insert_lost_records #2 c 5 e 20f103 n 62b
...

Re: how to avoid lost trace records?

[Olaf Hering]

On Fri, Nov 19, Olaf Hering wrote:

> 
> Today I inspected the xenalyze and the dump-raw output and noticed that
> huge number of lost trace records, even when booted with tbuf_size=200:
> 
> grep -wn 1f001 log.sles11_6.xentrace.txt.dump-raw
> 274438:R p 5 o000000000063ffd4    1f001 4 t0000006d215b3c6b [ b6aed 57fff 9e668fb6 51 ]
...
> That means more than 740K lost entries on cpu5,3,2,1,0.
> Is this expected?

After reading the sources more carefully, its clear now.
There are a few constraints:

If booted with tbuf_size=N, tracing starts right away and fills up the
buffer until xentrace collects its content. So entries will be lost.

Once I just ran xentrace -e all > output, which filled up the whole disk
during my testing. So I changed the way to collect the output to a
compressed file:

 # mknod pipe p
 # gzip -v9 < pipe > output.gz &
 # xentrace -e all pipe &

This means xentrace will stall until gzip has made room in the pipe.
Which also means xentrace cant collect more data from the tracebuffer
while waiting. So that is the reason for the lost entries.

Now I changed T_INFO_PAGES in trace.c from 2 to 16, and reduced the
compression rate to speedup gzip emptying the pipe.

 # mknod pipe p
 # nice -n -19 gzip -v1 < pipe > output.gz &
 # nice -n -19 xentrace -s 1 -S 2031 -e $(( 0x10f000 )) pipe &


This means no more lost entries even with more than one guest running.


Olaf

Re: Re: how to avoid lost trace records?

[George Dunlap]

Olaf,

Dang, 8 megs per cpu -- but I guess that's really not so much overhead
on a big machine; and it's definitely worth getting around the lost
records issue.  Send the T_INFO_PAGES patch to the list, and see what
Keir thinks.

There's probably a way to modify xenalyze to do start up gzip
directly; may not be a bad idea.

 -George

On Sat, Nov 20, 2010 at 8:21 PM, Olaf Hering <olaf@aepfle.de> wrote:
> On Fri, Nov 19, Olaf Hering wrote:
>
>>
>> Today I inspected the xenalyze and the dump-raw output and noticed that
>> huge number of lost trace records, even when booted with tbuf_size=200:
>>
>> grep -wn 1f001 log.sles11_6.xentrace.txt.dump-raw
>> 274438:R p 5 o000000000063ffd4    1f001 4 t0000006d215b3c6b [ b6aed 57fff 9e668fb6 51 ]
> ...
>> That means more than 740K lost entries on cpu5,3,2,1,0.
>> Is this expected?
>
> After reading the sources more carefully, its clear now.
> There are a few constraints:
>
> If booted with tbuf_size=N, tracing starts right away and fills up the
> buffer until xentrace collects its content. So entries will be lost.
>
> Once I just ran xentrace -e all > output, which filled up the whole disk
> during my testing. So I changed the way to collect the output to a
> compressed file:
>
>  # mknod pipe p
>  # gzip -v9 < pipe > output.gz &
>  # xentrace -e all pipe &
>
> This means xentrace will stall until gzip has made room in the pipe.
> Which also means xentrace cant collect more data from the tracebuffer
> while waiting. So that is the reason for the lost entries.
>
> Now I changed T_INFO_PAGES in trace.c from 2 to 16, and reduced the
> compression rate to speedup gzip emptying the pipe.
>
>  # mknod pipe p
>  # nice -n -19 gzip -v1 < pipe > output.gz &
>  # nice -n -19 xentrace -s 1 -S 2031 -e $(( 0x10f000 )) pipe &
>
>
> This means no more lost entries even with more than one guest running.
>
>
> Olaf
>
>
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xensource.com
> http://lists.xensource.com/xen-devel
>

Re: Re: how to avoid lost trace records?

[Olaf Hering]

On Mon, Nov 22, George Dunlap wrote:

> Olaf,
> 
> Dang, 8 megs per cpu -- but I guess that's really not so much overhead
> on a big machine; and it's definitely worth getting around the lost
> records issue.  Send the T_INFO_PAGES patch to the list, and see what
> Keir thinks.

Yes, will do.

Sometimes there is a boost of records, like set_p2m_entry and the like.
They all happen on the same cpu, so the per_cpu buffer fills up quickly.
And thats what I'm debugging right now. Too bad, tracing adds overhead
so the bug disappears. So, back to reading source code and find the race
that way.

Olaf

Re: Re: how to avoid lost trace records?

[George Dunlap]

Hmm, there's a stack of patches for bugs related to the p2m / PoD /
ept code fixed in XenServer product that I neglected to send upstream
when I found.  Unfortunately the p2m code has changed sufficiently
since 3.4 that they don't apply cleanly, and I've had a lot of trouble
actually getting a usable OSS system that I can test the p2m code on.

If you like, I can post the raw patches to the list, and you can see
if any of your bugs might be fixed among them...

 -George

On Mon, Nov 22, 2010 at 12:40 PM, Olaf Hering <olaf@aepfle.de> wrote:
> On Mon, Nov 22, George Dunlap wrote:
>
>> Olaf,
>>
>> Dang, 8 megs per cpu -- but I guess that's really not so much overhead
>> on a big machine; and it's definitely worth getting around the lost
>> records issue.  Send the T_INFO_PAGES patch to the list, and see what
>> Keir thinks.
>
> Yes, will do.
>
> Sometimes there is a boost of records, like set_p2m_entry and the like.
> They all happen on the same cpu, so the per_cpu buffer fills up quickly.
> And thats what I'm debugging right now. Too bad, tracing adds overhead
> so the bug disappears. So, back to reading source code and find the race
> that way.
>
> Olaf
>

Re: Re: how to avoid lost trace records?

[Keir Fraser]

Is there a good reason that T_INFO_PAGES cannot be specified dynamically by
the toolstack, when enabling tracing? It doesn't seem particularly necessary
that this piece of policy is expressed statically within the hypervisor.

 -- Keir

On 22/11/2010 11:53, "George Dunlap" <dunlapg@umich.edu> wrote:

> Olaf,
> 
> Dang, 8 megs per cpu -- but I guess that's really not so much overhead
> on a big machine; and it's definitely worth getting around the lost
> records issue.  Send the T_INFO_PAGES patch to the list, and see what
> Keir thinks.
> 
> There's probably a way to modify xenalyze to do start up gzip
> directly; may not be a bad idea.
> 
>  -George
> 
> On Sat, Nov 20, 2010 at 8:21 PM, Olaf Hering <olaf@aepfle.de> wrote:
>> On Fri, Nov 19, Olaf Hering wrote:
>> 
>>> 
>>> Today I inspected the xenalyze and the dump-raw output and noticed that
>>> huge number of lost trace records, even when booted with tbuf_size=200:
>>> 
>>> grep -wn 1f001 log.sles11_6.xentrace.txt.dump-raw
>>> 274438:R p 5 o000000000063ffd4    1f001 4 t0000006d215b3c6b [ b6aed 57fff
>>> 9e668fb6 51 ]
>> ...
>>> That means more than 740K lost entries on cpu5,3,2,1,0.
>>> Is this expected?
>> 
>> After reading the sources more carefully, its clear now.
>> There are a few constraints:
>> 
>> If booted with tbuf_size=N, tracing starts right away and fills up the
>> buffer until xentrace collects its content. So entries will be lost.
>> 
>> Once I just ran xentrace -e all > output, which filled up the whole disk
>> during my testing. So I changed the way to collect the output to a
>> compressed file:
>> 
>>  # mknod pipe p
>>  # gzip -v9 < pipe > output.gz &
>>  # xentrace -e all pipe &
>> 
>> This means xentrace will stall until gzip has made room in the pipe.
>> Which also means xentrace cant collect more data from the tracebuffer
>> while waiting. So that is the reason for the lost entries.
>> 
>> Now I changed T_INFO_PAGES in trace.c from 2 to 16, and reduced the
>> compression rate to speedup gzip emptying the pipe.
>> 
>>  # mknod pipe p
>>  # nice -n -19 gzip -v1 < pipe > output.gz &
>>  # nice -n -19 xentrace -s 1 -S 2031 -e $(( 0x10f000 )) pipe &
>> 
>> 
>> This means no more lost entries even with more than one guest running.
>> 
>> 
>> Olaf
>> 
>> 
>> _______________________________________________
>> 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

Re: Re: how to avoid lost trace records?

[George Dunlap]

I think the main reason for making T_INFO_PAGES static was to limit
the number of moving-part-changes when I went to the non-contiguous
trace buffer allocation.  Looking through the code, I don't see any
reason it couldn't be allocated dynamically as well.

Hmm... it would also have required an API change, which would have
meant a lot of plumbing changes as well.  Making it a xen command-line
parameter should be really simple, and then we can look at making it
toolstack configurable.

Actually, since the trace buffers can only be set once anyway, maybe
the best thing to do is calculate the number of t_info pages based on
the requested trace_buf size.  Then the interface doesn't have to
change at all.

I'll take a look at it sometime in the next week or two.

 -George

On Mon, Nov 22, 2010 at 1:46 PM, Keir Fraser <keir@xen.org> wrote:
> Is there a good reason that T_INFO_PAGES cannot be specified dynamically by
> the toolstack, when enabling tracing? It doesn't seem particularly necessary
> that this piece of policy is expressed statically within the hypervisor.
>
>  -- Keir
>
> On 22/11/2010 11:53, "George Dunlap" <dunlapg@umich.edu> wrote:
>
>> Olaf,
>>
>> Dang, 8 megs per cpu -- but I guess that's really not so much overhead
>> on a big machine; and it's definitely worth getting around the lost
>> records issue.  Send the T_INFO_PAGES patch to the list, and see what
>> Keir thinks.
>>
>> There's probably a way to modify xenalyze to do start up gzip
>> directly; may not be a bad idea.
>>
>>  -George
>>
>> On Sat, Nov 20, 2010 at 8:21 PM, Olaf Hering <olaf@aepfle.de> wrote:
>>> On Fri, Nov 19, Olaf Hering wrote:
>>>
>>>>
>>>> Today I inspected the xenalyze and the dump-raw output and noticed that
>>>> huge number of lost trace records, even when booted with tbuf_size=200:
>>>>
>>>> grep -wn 1f001 log.sles11_6.xentrace.txt.dump-raw
>>>> 274438:R p 5 o000000000063ffd4    1f001 4 t0000006d215b3c6b [ b6aed 57fff
>>>> 9e668fb6 51 ]
>>> ...
>>>> That means more than 740K lost entries on cpu5,3,2,1,0.
>>>> Is this expected?
>>>
>>> After reading the sources more carefully, its clear now.
>>> There are a few constraints:
>>>
>>> If booted with tbuf_size=N, tracing starts right away and fills up the
>>> buffer until xentrace collects its content. So entries will be lost.
>>>
>>> Once I just ran xentrace -e all > output, which filled up the whole disk
>>> during my testing. So I changed the way to collect the output to a
>>> compressed file:
>>>
>>>  # mknod pipe p
>>>  # gzip -v9 < pipe > output.gz &
>>>  # xentrace -e all pipe &
>>>
>>> This means xentrace will stall until gzip has made room in the pipe.
>>> Which also means xentrace cant collect more data from the tracebuffer
>>> while waiting. So that is the reason for the lost entries.
>>>
>>> Now I changed T_INFO_PAGES in trace.c from 2 to 16, and reduced the
>>> compression rate to speedup gzip emptying the pipe.
>>>
>>>  # mknod pipe p
>>>  # nice -n -19 gzip -v1 < pipe > output.gz &
>>>  # nice -n -19 xentrace -s 1 -S 2031 -e $(( 0x10f000 )) pipe &
>>>
>>>
>>> This means no more lost entries even with more than one guest running.
>>>
>>>
>>> Olaf
>>>
>>>
>>> _______________________________________________
>>> 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
>
>
>
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xensource.com
> http://lists.xensource.com/xen-devel
>

Re: Re: how to avoid lost trace records?

[Olaf Hering]

[ Sorry, this mutt process was suspended and I didnt notice ... ]

On Mon, Nov 22, George Dunlap wrote:

> Olaf,
> 
> Dang, 8 megs per cpu -- but I guess that's really not so much overhead
> on a big machine; and it's definitely worth getting around the lost
> records issue.  Send the T_INFO_PAGES patch to the list, and see what
> Keir thinks.

The change is as simple as this, for xen-unstable. 4.0 needs to add the
get_order_from_pages() for alloc_xenheap_pages() calls.

A dynamic trace buffer allocation, and also allowing dynamic mask as
cmdline option, should be added. I have added this line to trace.c to
allow an event mask during booting:

integer_param("tbuf_event_mask", tb_event_mask);

Olaf

---
 xen/common/trace.c |    3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

--- xen-unstable.hg-4.1.22415.orig/xen/common/trace.c
+++ xen-unstable.hg-4.1.22415/xen/common/trace.c
@@ -48,7 +48,8 @@ integer_param("tbuf_size", opt_tbuf_size
 
 /* Pointers to the meta-data objects for all system trace buffers */
 static struct t_info *t_info;
-#define T_INFO_PAGES 2  /* Size fixed at 2 pages for now. */
+#define T_INFO_PAGES_ORDER 1  /* Size fixed at 2 pages for now. */
+#define T_INFO_PAGES (1 << T_INFO_PAGES_ORDER)
 #define T_INFO_SIZE ((T_INFO_PAGES)*(PAGE_SIZE))
 static DEFINE_PER_CPU_READ_MOSTLY(struct t_buf *, t_bufs);
 static DEFINE_PER_CPU_READ_MOSTLY(unsigned char *, t_data);

Re: Re: how to avoid lost trace records?

[Keir Fraser]

On 25/11/2010 21:04, "Olaf Hering" <olaf@aepfle.de> wrote:

> --- xen-unstable.hg-4.1.22415.orig/xen/common/trace.c
> +++ xen-unstable.hg-4.1.22415/xen/common/trace.c
> @@ -48,7 +48,8 @@ integer_param("tbuf_size", opt_tbuf_size
>  
>  /* Pointers to the meta-data objects for all system trace buffers */
>  static struct t_info *t_info;
> -#define T_INFO_PAGES 2  /* Size fixed at 2 pages for now. */
> +#define T_INFO_PAGES_ORDER 1  /* Size fixed at 2 pages for now. */
> +#define T_INFO_PAGES (1 << T_INFO_PAGES_ORDER)
>  #define T_INFO_SIZE ((T_INFO_PAGES)*(PAGE_SIZE))
>  static DEFINE_PER_CPU_READ_MOSTLY(struct t_buf *, t_bufs);
>  static DEFINE_PER_CPU_READ_MOSTLY(unsigned char *, t_data);

This patch looks like it has no effect whatsoever.

 -- Keir