xen-devel.lists.xenproject.org archive mirror
 help / color / mirror / Atom feed
* [PATCH] updates to the format file for xentrace (v1).
@ 2013-03-12 18:34 Konrad Rzeszutek Wilk
  2013-03-12 18:34 ` [PATCH 1/2] trace: Use correct trace class for power management changes Konrad Rzeszutek Wilk
                   ` (2 more replies)
  0 siblings, 3 replies; 7+ messages in thread
From: Konrad Rzeszutek Wilk @ 2013-03-12 18:34 UTC (permalink / raw)
  To: george.dunlap, david.vrabel, xen-devel

While trying to troubleshoot an guest and hypervisor freeze I noticed
that there were a couple of various 'unknown' in the trace file.

This fixes the majority of them.

 tools/xentrace/formats | 13 +++++++++++--
 1 file changed, 11 insertions(+), 2 deletions(-)


Konrad Rzeszutek Wilk (2):
      trace: Use correct trace class for power management changes.
      trace: Add trace events for IRQ activities.

Please review and if OK apply to the tree.

^ permalink raw reply	[flat|nested] 7+ messages in thread

* [PATCH 1/2] trace: Use correct trace class for power management changes.
  2013-03-12 18:34 [PATCH] updates to the format file for xentrace (v1) Konrad Rzeszutek Wilk
@ 2013-03-12 18:34 ` Konrad Rzeszutek Wilk
  2013-03-13 10:37   ` George Dunlap
  2013-03-12 18:34 ` [PATCH 2/2] trace: Add trace events for IRQ activities Konrad Rzeszutek Wilk
  2013-03-12 18:59 ` [PATCH] updates to the format file for xentrace (v1) David Vrabel
  2 siblings, 1 reply; 7+ messages in thread
From: Konrad Rzeszutek Wilk @ 2013-03-12 18:34 UTC (permalink / raw)
  To: george.dunlap, david.vrabel, xen-devel; +Cc: Konrad Rzeszutek Wilk

Previous to this patch we would see in the trace file:

CPU28  1753503175371 (+    8496)  unknown (0x0000000000801002)  [ 0x00000004 0x4158a498 0x000003a1 0x000027e6 0x00000000 0x00000000 0x00000000 ]
CPU28  1753505321239 (+ 2145868)  unknown (0x0000000000801003)  [ 0x00000004 0x4166dca7 0x000000fa 0x00000000 0x00000000 0x00000000 0x00000000 ]
CPU28  1753505343756 (+   22517)  unknown (0x0000000000801002)  [ 0x00000004 0x41670fe5 0x00001284 0x00003766 0x00000000 0x00000000 0x00000000 ]
CPU28  1753521413711 (+16069955)  unknown (0x0000000000801003)  [ 0x00000004 0x41d1e02c 0x000000ab 0x00000000 0x00000000 0x00000000 0x00000000 ]

instead of:
CPU28  1753503175371 (+    8496)  cpu_idle_entry  [ C0 -> C4, acpi_pm_tick = 1096328344, expected = 929us, predicted = 10214us ]
CPU28  1753505321239 (+ 2145868)  cpu_idle_exit   [ C4 -> C0, acpi_pm_tick = 1097260199, irq = 250 0 0 0 ]
CPU28  1753505343756 (+   22517)  cpu_idle_entry  [ C0 -> C4, acpi_pm_tick = 1097273317, expected = 4740us, predicted = 14182us ]
CPU28  1753521413711 (+16069955)  cpu_idle_exit   [ C4 -> C0, acpi_pm_tick = 1104273452, irq = 171 0 0 0 ]

The patch that added the cpu_idle_[entry|exit] was using the
TRC_HW_IRQ class (0x00802000) instead of TRC_HW_PM (0x00801000)
as a base.

Signed-off-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
---
 tools/xentrace/formats | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index 928e1d7..b4e3d05 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -139,5 +139,5 @@
 0x0040f10f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  shadow_emulate_resync_only        [ gfn = 0x%(2)08x%(1)08x ]
 
 0x00801001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_freq_change [ %(1)dMHz -> %(2)dMHz ]
-0x00802001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_entry  [ C0 -> C%(1)d, acpi_pm_tick = %(2)d, expected = %(3)dus, predicted = %(4)dus ]
-0x00802002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_exit   [ C%(1)d -> C0, acpi_pm_tick = %(2)d, irq = %(3)d %(4)d %(5)d %(6)d ]
+0x00801002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_entry  [ C0 -> C%(1)d, acpi_pm_tick = %(2)d, expected = %(3)dus, predicted = %(4)dus ]
+0x00801003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_exit   [ C%(1)d -> C0, acpi_pm_tick = %(2)d, irq = %(3)d %(4)d %(5)d %(6)d ]
-- 
1.8.0.2

^ permalink raw reply related	[flat|nested] 7+ messages in thread

* [PATCH 2/2] trace: Add trace events for IRQ activities.
  2013-03-12 18:34 [PATCH] updates to the format file for xentrace (v1) Konrad Rzeszutek Wilk
  2013-03-12 18:34 ` [PATCH 1/2] trace: Use correct trace class for power management changes Konrad Rzeszutek Wilk
@ 2013-03-12 18:34 ` Konrad Rzeszutek Wilk
  2013-03-13 10:38   ` George Dunlap
  2013-03-12 18:59 ` [PATCH] updates to the format file for xentrace (v1) David Vrabel
  2 siblings, 1 reply; 7+ messages in thread
From: Konrad Rzeszutek Wilk @ 2013-03-12 18:34 UTC (permalink / raw)
  To: george.dunlap, david.vrabel, xen-devel; +Cc: Konrad Rzeszutek Wilk

This expands the format to include the class of TRC_HW_IRQ.
This means that instead of:

CPU28  1753521436727 (+    3252)  unknown (0x0000000000802008)  [ 0x0000006c 0x4605709c 0x4605b682 0x00000000 0x00000000 0x00000000 0x00000000 ]

we now see:

CPU28  1753521436727 (+    3252)  do_irq [ irq = 108, began = 1174761628us, ended = 1174779522us ]

Signed-off-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
---
 tools/xentrace/formats | 9 +++++++++
 1 file changed, 9 insertions(+)

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index b4e3d05..00f0263 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -141,3 +141,12 @@
 0x00801001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_freq_change [ %(1)dMHz -> %(2)dMHz ]
 0x00801002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_entry  [ C0 -> C%(1)d, acpi_pm_tick = %(2)d, expected = %(3)dus, predicted = %(4)dus ]
 0x00801003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_exit   [ C%(1)d -> C0, acpi_pm_tick = %(2)d, irq = %(3)d %(4)d %(5)d %(6)d ]
+
+0x00802001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cleanup_move_delayed [ irq = %(1)d, vector 0x%(2)x on CPU%(3)d ]
+0x00802002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cleanup_move [ irq = %(1)d, vector 0x%(2)x on CPU%(3)d ]
+0x00802003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  bind_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ]
+0x00802004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  clear_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ]
+0x00802005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  move_vector [ irq = %(1)d had vector 0x%(2)x on CPU%(3)d ]
+0x00802006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  assign_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ]
+0x00802007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  bogus_vector [ 0x%(1)x ]
+0x00802008  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_irq [ irq = %(1)d, began = %(2)dus, ended = %(3)dus ]
-- 
1.8.0.2

^ permalink raw reply related	[flat|nested] 7+ messages in thread

* Re: [PATCH] updates to the format file for xentrace (v1).
  2013-03-12 18:34 [PATCH] updates to the format file for xentrace (v1) Konrad Rzeszutek Wilk
  2013-03-12 18:34 ` [PATCH 1/2] trace: Use correct trace class for power management changes Konrad Rzeszutek Wilk
  2013-03-12 18:34 ` [PATCH 2/2] trace: Add trace events for IRQ activities Konrad Rzeszutek Wilk
@ 2013-03-12 18:59 ` David Vrabel
  2013-03-12 20:14   ` Konrad Rzeszutek Wilk
  2 siblings, 1 reply; 7+ messages in thread
From: David Vrabel @ 2013-03-12 18:59 UTC (permalink / raw)
  To: Konrad Rzeszutek Wilk; +Cc: xen-devel, george.dunlap, david.vrabel

On 12/03/13 18:34, Konrad Rzeszutek Wilk wrote:
> While trying to troubleshoot an guest and hypervisor freeze I noticed
> that there were a couple of various 'unknown' in the trace file.

Do these event show up correctly with xenalyze?

David

> This fixes the majority of them.
> 
>  tools/xentrace/formats | 13 +++++++++++--
>  1 file changed, 11 insertions(+), 2 deletions(-)
> 
> 
> Konrad Rzeszutek Wilk (2):
>       trace: Use correct trace class for power management changes.
>       trace: Add trace events for IRQ activities.
> 
> Please review and if OK apply to the tree.
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 7+ messages in thread

* Re: [PATCH] updates to the format file for xentrace (v1).
  2013-03-12 18:59 ` [PATCH] updates to the format file for xentrace (v1) David Vrabel
@ 2013-03-12 20:14   ` Konrad Rzeszutek Wilk
  0 siblings, 0 replies; 7+ messages in thread
From: Konrad Rzeszutek Wilk @ 2013-03-12 20:14 UTC (permalink / raw)
  To: David Vrabel; +Cc: xen-devel, george.dunlap

On Tue, Mar 12, 2013 at 06:59:36PM +0000, David Vrabel wrote:
> On 12/03/13 18:34, Konrad Rzeszutek Wilk wrote:
> > While trying to troubleshoot an guest and hypervisor freeze I noticed
> > that there were a couple of various 'unknown' in the trace file.
> 
> Do these event show up correctly with xenalyze?

Yes:

38.704969625 ----------------||-|--|--|-x---- d32767v27 pm_idle_end c4
] 38.704976414 ----------------||-|--|--|-x---- d32767v27   2800e(2:8:e) 2 [ 7fff 5e8e8b3 ]
] 38.704976785 ----------------||-|--|--|-x---- d32767v27   2800f(2:8:f) 3 [ 0 9e76 1c9c380 ]

for the power managements. For IRQ:

  38.705256409 ----------------||-|--x--|-|---- d32767v22 irq_handled irq 67 15633 (1409890175,1409905808)
] 38.705262071 ----------------||-|--x--|-|---- d32767v22   2800e(2:8:e) 2 [ 7fff 158c7 ]
] 38.705262364 ----------------||-|--x--|-|---- d32767v22   2800f(2:8:f) 3 [ 0 2126 1c9c380 ]
] 38.705262697 ----------------||-|--x--|-|---- d32767v22   2800a(2:8:a) 4 [ 7fff 16 0 a ]

so yes. They do show in xenalyze.

> 
> David
> 
> > This fixes the majority of them.
> > 
> >  tools/xentrace/formats | 13 +++++++++++--
> >  1 file changed, 11 insertions(+), 2 deletions(-)
> > 
> > 
> > Konrad Rzeszutek Wilk (2):
> >       trace: Use correct trace class for power management changes.
> >       trace: Add trace events for IRQ activities.
> > 
> > Please review and if OK apply to the tree.
> > 
> > 
> > _______________________________________________
> > Xen-devel mailing list
> > Xen-devel@lists.xen.org
> > http://lists.xen.org/xen-devel
> 

^ permalink raw reply	[flat|nested] 7+ messages in thread

* Re: [PATCH 1/2] trace: Use correct trace class for power management changes.
  2013-03-12 18:34 ` [PATCH 1/2] trace: Use correct trace class for power management changes Konrad Rzeszutek Wilk
@ 2013-03-13 10:37   ` George Dunlap
  0 siblings, 0 replies; 7+ messages in thread
From: George Dunlap @ 2013-03-13 10:37 UTC (permalink / raw)
  To: Konrad Rzeszutek Wilk; +Cc: xen-devel@lists.xensource.com, David Vrabel

On 12/03/13 18:34, Konrad Rzeszutek Wilk wrote:
> Previous to this patch we would see in the trace file:
>
> CPU28  1753503175371 (+    8496)  unknown (0x0000000000801002)  [ 0x00000004 0x4158a498 0x000003a1 0x000027e6 0x00000000 0x00000000 0x00000000 ]
> CPU28  1753505321239 (+ 2145868)  unknown (0x0000000000801003)  [ 0x00000004 0x4166dca7 0x000000fa 0x00000000 0x00000000 0x00000000 0x00000000 ]
> CPU28  1753505343756 (+   22517)  unknown (0x0000000000801002)  [ 0x00000004 0x41670fe5 0x00001284 0x00003766 0x00000000 0x00000000 0x00000000 ]
> CPU28  1753521413711 (+16069955)  unknown (0x0000000000801003)  [ 0x00000004 0x41d1e02c 0x000000ab 0x00000000 0x00000000 0x00000000 0x00000000 ]
>
> instead of:
> CPU28  1753503175371 (+    8496)  cpu_idle_entry  [ C0 -> C4, acpi_pm_tick = 1096328344, expected = 929us, predicted = 10214us ]
> CPU28  1753505321239 (+ 2145868)  cpu_idle_exit   [ C4 -> C0, acpi_pm_tick = 1097260199, irq = 250 0 0 0 ]
> CPU28  1753505343756 (+   22517)  cpu_idle_entry  [ C0 -> C4, acpi_pm_tick = 1097273317, expected = 4740us, predicted = 14182us ]
> CPU28  1753521413711 (+16069955)  cpu_idle_exit   [ C4 -> C0, acpi_pm_tick = 1104273452, irq = 171 0 0 0 ]
>
> The patch that added the cpu_idle_[entry|exit] was using the
> TRC_HW_IRQ class (0x00802000) instead of TRC_HW_PM (0x00801000)
> as a base.
>
> Signed-off-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>

Acked-by: George Dunlap <george.dunlap@eu.citrix.com>

> ---
>   tools/xentrace/formats | 4 ++--
>   1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/tools/xentrace/formats b/tools/xentrace/formats
> index 928e1d7..b4e3d05 100644
> --- a/tools/xentrace/formats
> +++ b/tools/xentrace/formats
> @@ -139,5 +139,5 @@
>   0x0040f10f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  shadow_emulate_resync_only        [ gfn = 0x%(2)08x%(1)08x ]
>   
>   0x00801001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_freq_change [ %(1)dMHz -> %(2)dMHz ]
> -0x00802001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_entry  [ C0 -> C%(1)d, acpi_pm_tick = %(2)d, expected = %(3)dus, predicted = %(4)dus ]
> -0x00802002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_exit   [ C%(1)d -> C0, acpi_pm_tick = %(2)d, irq = %(3)d %(4)d %(5)d %(6)d ]
> +0x00801002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_entry  [ C0 -> C%(1)d, acpi_pm_tick = %(2)d, expected = %(3)dus, predicted = %(4)dus ]
> +0x00801003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_exit   [ C%(1)d -> C0, acpi_pm_tick = %(2)d, irq = %(3)d %(4)d %(5)d %(6)d ]

^ permalink raw reply	[flat|nested] 7+ messages in thread

* Re: [PATCH 2/2] trace: Add trace events for IRQ activities.
  2013-03-12 18:34 ` [PATCH 2/2] trace: Add trace events for IRQ activities Konrad Rzeszutek Wilk
@ 2013-03-13 10:38   ` George Dunlap
  0 siblings, 0 replies; 7+ messages in thread
From: George Dunlap @ 2013-03-13 10:38 UTC (permalink / raw)
  To: Konrad Rzeszutek Wilk; +Cc: xen-devel@lists.xensource.com, David Vrabel

On 12/03/13 18:34, Konrad Rzeszutek Wilk wrote:
> This expands the format to include the class of TRC_HW_IRQ.
> This means that instead of:
>
> CPU28  1753521436727 (+    3252)  unknown (0x0000000000802008)  [ 0x0000006c 0x4605709c 0x4605b682 0x00000000 0x00000000 0x00000000 0x00000000 ]
>
> we now see:
>
> CPU28  1753521436727 (+    3252)  do_irq [ irq = 108, began = 1174761628us, ended = 1174779522us ]
>
> Signed-off-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>

Acked-by: George Dunlap <george.dunlap@eu.citrix.com>

> ---
>   tools/xentrace/formats | 9 +++++++++
>   1 file changed, 9 insertions(+)
>
> diff --git a/tools/xentrace/formats b/tools/xentrace/formats
> index b4e3d05..00f0263 100644
> --- a/tools/xentrace/formats
> +++ b/tools/xentrace/formats
> @@ -141,3 +141,12 @@
>   0x00801001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_freq_change [ %(1)dMHz -> %(2)dMHz ]
>   0x00801002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_entry  [ C0 -> C%(1)d, acpi_pm_tick = %(2)d, expected = %(3)dus, predicted = %(4)dus ]
>   0x00801003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_idle_exit   [ C%(1)d -> C0, acpi_pm_tick = %(2)d, irq = %(3)d %(4)d %(5)d %(6)d ]
> +
> +0x00802001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cleanup_move_delayed [ irq = %(1)d, vector 0x%(2)x on CPU%(3)d ]
> +0x00802002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cleanup_move [ irq = %(1)d, vector 0x%(2)x on CPU%(3)d ]
> +0x00802003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  bind_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ]
> +0x00802004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  clear_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ]
> +0x00802005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  move_vector [ irq = %(1)d had vector 0x%(2)x on CPU%(3)d ]
> +0x00802006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  assign_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ]
> +0x00802007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  bogus_vector [ 0x%(1)x ]
> +0x00802008  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_irq [ irq = %(1)d, began = %(2)dus, ended = %(3)dus ]

^ permalink raw reply	[flat|nested] 7+ messages in thread

end of thread, other threads:[~2013-03-13 10:38 UTC | newest]

Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-03-12 18:34 [PATCH] updates to the format file for xentrace (v1) Konrad Rzeszutek Wilk
2013-03-12 18:34 ` [PATCH 1/2] trace: Use correct trace class for power management changes Konrad Rzeszutek Wilk
2013-03-13 10:37   ` George Dunlap
2013-03-12 18:34 ` [PATCH 2/2] trace: Add trace events for IRQ activities Konrad Rzeszutek Wilk
2013-03-13 10:38   ` George Dunlap
2013-03-12 18:59 ` [PATCH] updates to the format file for xentrace (v1) David Vrabel
2013-03-12 20:14   ` Konrad Rzeszutek Wilk

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).