* [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
* 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
* [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 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
* 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