[PATCH 00/16] Hyper-V: add tracing to VMBus module and trace all messages

From: Vitaly Kuznetsov
Date: Wed Sep 20 2017 - 13:22:16 EST


Messages between guest and host are used in Hyper-V as control flow. To
simplify debugging various issues which are often hard to reproduce add
tracepoints to all message senders and handlers. This is not a performance
critical path and tracing overhead should be negligible.

The example usage and output is:

Enable all tracing events:
# echo 1 > /sys/kernel/debug/tracing/events/hyperv/enable

Do something which causes messages to be sent between host and guest, e.g.
hot remove a VMBus device.

Check events:
# cat /sys/kernel/debug/tracing/trace

# tracer: nop
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [005] .Ns. 465.923970: vmbus_on_msg_dpc: message 2 received
ksoftirqd/5-41 [005] ..s. 465.923998: vmbus_on_msg_dpc: message 2 received
kworker/5:1-64 [005] .... 465.924005: vmbus_on_message: processing message 2
kworker/5:1-64 [005] .... 465.924005: vmbus_onoffer_rescind: child_relid 0x16
<idle>-0 [005] ..s. 465.924114: vmbus_on_msg_dpc: message 2 received
<idle>-0 [005] ..s. 465.924120: vmbus_on_msg_dpc: message 2 received
<idle>-0 [005] .Ns. 465.924502: vmbus_on_msg_dpc: message 2 received
kworker/5:2-208 [005] .... 465.924520: vmbus_on_message: processing message 2
kworker/5:2-208 [005] .... 465.924520: vmbus_onoffer_rescind: child_relid 0x18
kworker/5:0-2533 [005] .... 465.924713: vmbus_on_message: processing message 2
kworker/5:0-2533 [005] .... 465.924713: vmbus_onoffer_rescind: child_relid 0x17
kworker/5:3-2534 [005] .... 465.924810: vmbus_on_message: processing message 2
kworker/5:3-2534 [005] .... 465.924810: vmbus_onoffer_rescind: child_relid 0x15
kworker/5:4-2535 [005] .... 465.924900: vmbus_on_message: processing message 2
kworker/5:4-2535 [005] .... 465.924901: vmbus_onoffer_rescind: child_relid 0x10
kworker/5:4-2535 [005] .... 465.932588: vmbus_close_internal: sending child_relid 0x15, ret 0
kworker/5:4-2535 [005] .... 465.932623: vmbus_close_internal: sending child_relid 0x16, ret 0
kworker/5:4-2535 [005] .... 465.932656: vmbus_close_internal: sending child_relid 0x17, ret 0
kworker/5:4-2535 [005] .... 465.932683: vmbus_close_internal: sending child_relid 0x18, ret 0
kworker/5:4-2535 [005] .... 465.932709: vmbus_close_internal: sending child_relid 0x10, ret 0
kworker/5:4-2535 [005] .... 465.986417: vmbus_release_relid: sending child_relid 0x10, ret 0

CHANNELMSG_UNLOAD/CHANNELMSG_UNLOAD_RESPONSE are not traced as these are
mostly used on crash.

Vitaly Kuznetsov (16):
hyper-v: trace vmbus_on_msg_dpc()
hyper-v: trace vmbus_on_message()
hyper-v: trace vmbus_onoffer()
hyper-v: trace vmbus_onoffer_rescind()
hyper-v: trace vmbus_onopen_result()
hyper-v: trace vmbus_ongpadl_created()
hyper-v: trace vmbus_ongpadl_torndown()
hyper-v: trace vmbus_onversion_response()
hyper-v: trace vmbus_request_offers()
hyper-v: trace vmbus_open()
hyper-v: trace vmbus_close_internal()
hyper-v: trace vmbus_establish_gpadl()
hyper-v: trace vmbus_teardown_gpadl()
hyper-v: trace vmbus_negotiate_version()
hyper-v: trace vmbus_release_relid()
hyper-v: trace vmbus_send_tl_connect_request()

drivers/hv/Makefile | 4 +-
drivers/hv/channel.c | 19 ++-
drivers/hv/channel_mgmt.c | 26 +++-
drivers/hv/connection.c | 3 +
drivers/hv/hv_trace.c | 4 +
drivers/hv/hv_trace.h | 302 ++++++++++++++++++++++++++++++++++++++++++++++
drivers/hv/hyperv_vmbus.h | 2 +
drivers/hv/vmbus_drv.c | 2 +
8 files changed, 357 insertions(+), 5 deletions(-)
create mode 100644 drivers/hv/hv_trace.c
create mode 100644 drivers/hv/hv_trace.h

--
2.13.5