Konrad Rzeszutek Wilk
2013-Mar-12 18:34 UTC
[PATCH] updates to the format file for xentrace (v1).
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.
Konrad Rzeszutek Wilk
2013-Mar-12 18:34 UTC
[PATCH 1/2] trace: Use correct trace class for power management changes.
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
Konrad Rzeszutek Wilk
2013-Mar-12 18:34 UTC
[PATCH 2/2] trace: Add trace events for IRQ activities.
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
David Vrabel
2013-Mar-12 18:59 UTC
Re: [PATCH] updates to the format file for xentrace (v1).
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
Konrad Rzeszutek Wilk
2013-Mar-12 20:14 UTC
Re: [PATCH] updates to the format file for xentrace (v1).
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 >
George Dunlap
2013-Mar-13 10:37 UTC
Re: [PATCH 1/2] trace: Use correct trace class for power management changes.
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 ]
George Dunlap
2013-Mar-13 10:38 UTC
Re: [PATCH 2/2] trace: Add trace events for IRQ activities.
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 ]