From ec9663812f32c03e36c8c2ccc83e52dd5a7486d9 Mon Sep 17 00:00:00 2001 From: Stephen Hemminger Date: Fri, 16 Mar 2018 15:44:28 -0700 Subject: [PATCH] hv_netvsc: add trace points This adds tracepoints to the driver which has proved useful in debugging startup and shutdown race conditions. Signed-off-by: Stephen Hemminger Signed-off-by: David S. Miller --- drivers/net/hyperv/Makefile | 2 +- drivers/net/hyperv/netvsc.c | 26 ++++- drivers/net/hyperv/netvsc_trace.c | 7 ++ drivers/net/hyperv/netvsc_trace.h | 182 ++++++++++++++++++++++++++++++ drivers/net/hyperv/rndis_filter.c | 5 + 5 files changed, 220 insertions(+), 2 deletions(-) create mode 100644 drivers/net/hyperv/netvsc_trace.c create mode 100644 drivers/net/hyperv/netvsc_trace.h diff --git a/drivers/net/hyperv/Makefile b/drivers/net/hyperv/Makefile index c8a66827100c..3f25b9c8ea59 100644 --- a/drivers/net/hyperv/Makefile +++ b/drivers/net/hyperv/Makefile @@ -1,3 +1,3 @@ obj-$(CONFIG_HYPERV_NET) += hv_netvsc.o -hv_netvsc-y := netvsc_drv.o netvsc.o rndis_filter.o +hv_netvsc-y := netvsc_drv.o netvsc.o rndis_filter.o netvsc_trace.o diff --git a/drivers/net/hyperv/netvsc.c b/drivers/net/hyperv/netvsc.c index 0265d703eb03..aa95e81af6e5 100644 --- a/drivers/net/hyperv/netvsc.c +++ b/drivers/net/hyperv/netvsc.c @@ -36,6 +36,7 @@ #include #include "hyperv_net.h" +#include "netvsc_trace.h" /* * Switch the data path from the synthetic interface to the VF @@ -57,6 +58,8 @@ void netvsc_switch_datapath(struct net_device *ndev, bool vf) init_pkt->msg.v4_msg.active_dp.active_datapath = NVSP_DATAPATH_SYNTHETIC; + trace_nvsp_send(ndev, init_pkt); + vmbus_sendpacket(dev->channel, init_pkt, sizeof(struct nvsp_message), (unsigned long)init_pkt, @@ -124,6 +127,8 @@ static void netvsc_revoke_buf(struct hv_device *device, revoke_packet->msg.v1_msg. revoke_recv_buf.id = NETVSC_RECEIVE_BUFFER_ID; + trace_nvsp_send(ndev, revoke_packet); + ret = vmbus_sendpacket(device->channel, revoke_packet, sizeof(struct nvsp_message), @@ -164,6 +169,8 @@ static void netvsc_revoke_buf(struct hv_device *device, revoke_packet->msg.v1_msg.revoke_send_buf.id = NETVSC_SEND_BUFFER_ID; + trace_nvsp_send(ndev, revoke_packet); + ret = vmbus_sendpacket(device->channel, revoke_packet, sizeof(struct nvsp_message), @@ -305,6 +312,8 @@ static int netvsc_init_buf(struct hv_device *device, init_packet->msg.v1_msg. send_recv_buf.id = NETVSC_RECEIVE_BUFFER_ID; + trace_nvsp_send(ndev, init_packet); + /* Send the gpadl notification request */ ret = vmbus_sendpacket(device->channel, init_packet, sizeof(struct nvsp_message), @@ -384,6 +393,8 @@ static int netvsc_init_buf(struct hv_device *device, net_device->send_buf_gpadl_handle; init_packet->msg.v1_msg.send_send_buf.id = NETVSC_SEND_BUFFER_ID; + trace_nvsp_send(ndev, init_packet); + /* Send the gpadl notification request */ ret = vmbus_sendpacket(device->channel, init_packet, sizeof(struct nvsp_message), @@ -452,6 +463,8 @@ static int negotiate_nvsp_ver(struct hv_device *device, init_packet->msg.init_msg.init.min_protocol_ver = nvsp_ver; init_packet->msg.init_msg.init.max_protocol_ver = nvsp_ver; + trace_nvsp_send(ndev, init_packet); + /* Send the init request */ ret = vmbus_sendpacket(device->channel, init_packet, sizeof(struct nvsp_message), @@ -484,6 +497,8 @@ static int negotiate_nvsp_ver(struct hv_device *device, init_packet->msg.v2_msg.send_ndis_config.capability.teaming = 1; } + trace_nvsp_send(ndev, init_packet); + ret = vmbus_sendpacket(device->channel, init_packet, sizeof(struct nvsp_message), (unsigned long)init_packet, @@ -496,6 +511,7 @@ static int netvsc_connect_vsp(struct hv_device *device, struct netvsc_device *net_device, const struct netvsc_device_info *device_info) { + struct net_device *ndev = hv_get_drvdata(device); static const u32 ver_list[] = { NVSP_PROTOCOL_VERSION_1, NVSP_PROTOCOL_VERSION_2, NVSP_PROTOCOL_VERSION_4, NVSP_PROTOCOL_VERSION_5 @@ -536,6 +552,8 @@ static int netvsc_connect_vsp(struct hv_device *device, send_ndis_ver.ndis_minor_ver = ndis_version & 0xFFFF; + trace_nvsp_send(ndev, init_packet); + /* Send the init request */ ret = vmbus_sendpacket(device->channel, init_packet, sizeof(struct nvsp_message), @@ -747,7 +765,7 @@ static inline int netvsc_send_pkt( struct sk_buff *skb) { struct nvsp_message nvmsg; - struct nvsp_1_message_send_rndis_packet * const rpkt = + struct nvsp_1_message_send_rndis_packet *rpkt = &nvmsg.msg.v1_msg.send_rndis_pkt; struct netvsc_channel * const nvchan = &net_device->chan_table[packet->q_idx]; @@ -776,6 +794,8 @@ static inline int netvsc_send_pkt( if (out_channel->rescind) return -ENODEV; + trace_nvsp_send_pkt(ndev, out_channel, rpkt); + if (packet->page_buf_cnt) { if (packet->cp_partial) pb += packet->rmsg_pgcnt; @@ -1079,6 +1099,8 @@ static int netvsc_receive(struct net_device *ndev, + vmxferpage_packet->ranges[i].byte_offset; u32 buflen = vmxferpage_packet->ranges[i].byte_count; + trace_rndis_recv(ndev, q_idx, data); + /* Pass it to the upper layer */ status = rndis_filter_receive(ndev, net_device, channel, data, buflen); @@ -1143,6 +1165,8 @@ static int netvsc_process_raw_pkt(struct hv_device *device, struct net_device_context *net_device_ctx = netdev_priv(ndev); struct nvsp_message *nvmsg = hv_pkt_data(desc); + trace_nvsp_recv(ndev, channel, nvmsg); + switch (desc->type) { case VM_PKT_COMP: netvsc_send_completion(net_device, channel, device, diff --git a/drivers/net/hyperv/netvsc_trace.c b/drivers/net/hyperv/netvsc_trace.c new file mode 100644 index 000000000000..bb0ce5a2bcd5 --- /dev/null +++ b/drivers/net/hyperv/netvsc_trace.c @@ -0,0 +1,7 @@ +/* SPDX-License-Identifier: GPL-2.0 */ +#include + +#include "hyperv_net.h" + +#define CREATE_TRACE_POINTS +#include "netvsc_trace.h" diff --git a/drivers/net/hyperv/netvsc_trace.h b/drivers/net/hyperv/netvsc_trace.h new file mode 100644 index 000000000000..f7585563dea5 --- /dev/null +++ b/drivers/net/hyperv/netvsc_trace.h @@ -0,0 +1,182 @@ +/* SPDX-License-Identifier: GPL-2.0 */ + +#if !defined(_NETVSC_TRACE_H) || defined(TRACE_HEADER_MULTI_READ) +#define _NETVSC_TRACE_H + +#include + +#undef TRACE_SYSTEM +#define TRACE_SYSTEM netvsc +#define TRACE_INCLUDE_FILE netvsc_trace + +TRACE_DEFINE_ENUM(RNDIS_MSG_PACKET); +TRACE_DEFINE_ENUM(RNDIS_MSG_INDICATE); +TRACE_DEFINE_ENUM(RNDIS_MSG_INIT); +TRACE_DEFINE_ENUM(RNDIS_MSG_INIT_C); +TRACE_DEFINE_ENUM(RNDIS_MSG_HALT); +TRACE_DEFINE_ENUM(RNDIS_MSG_QUERY); +TRACE_DEFINE_ENUM(RNDIS_MSG_QUERY_C); +TRACE_DEFINE_ENUM(RNDIS_MSG_SET); +TRACE_DEFINE_ENUM(RNDIS_MSG_SET_C); +TRACE_DEFINE_ENUM(RNDIS_MSG_RESET); +TRACE_DEFINE_ENUM(RNDIS_MSG_RESET_C); +TRACE_DEFINE_ENUM(RNDIS_MSG_KEEPALIVE); +TRACE_DEFINE_ENUM(RNDIS_MSG_KEEPALIVE_C); + +#define show_rndis_type(type) \ + __print_symbolic(type, \ + { RNDIS_MSG_PACKET, "PACKET" }, \ + { RNDIS_MSG_INDICATE, "INDICATE", }, \ + { RNDIS_MSG_INIT, "INIT", }, \ + { RNDIS_MSG_INIT_C, "INIT_C", }, \ + { RNDIS_MSG_HALT, "HALT", }, \ + { RNDIS_MSG_QUERY, "QUERY", }, \ + { RNDIS_MSG_QUERY_C, "QUERY_C", }, \ + { RNDIS_MSG_SET, "SET", }, \ + { RNDIS_MSG_SET_C, "SET_C", }, \ + { RNDIS_MSG_RESET, "RESET", }, \ + { RNDIS_MSG_RESET_C, "RESET_C", }, \ + { RNDIS_MSG_KEEPALIVE, "KEEPALIVE", }, \ + { RNDIS_MSG_KEEPALIVE_C, "KEEPALIVE_C", }) + +DECLARE_EVENT_CLASS(rndis_msg_class, + TP_PROTO(const struct net_device *ndev, u16 q, + const struct rndis_message *msg), + TP_ARGS(ndev, q, msg), + TP_STRUCT__entry( + __string( name, ndev->name ) + __field( u16, queue ) + __field( u32, req_id ) + __field( u32, msg_type ) + __field( u32, msg_len ) + ), + TP_fast_assign( + __assign_str(name, ndev->name); + __entry->queue = q; + __entry->req_id = msg->msg.init_req.req_id; + __entry->msg_type = msg->ndis_msg_type; + __entry->msg_len = msg->msg_len; + ), + TP_printk("dev=%s q=%u req=%#x type=%s msg_len=%u", + __get_str(name), __entry->queue, __entry->req_id, + show_rndis_type(__entry->msg_type), __entry->msg_len) +); + +DEFINE_EVENT(rndis_msg_class, rndis_send, + TP_PROTO(const struct net_device *ndev, u16 q, + const struct rndis_message *msg), + TP_ARGS(ndev, q, msg) +); + +DEFINE_EVENT(rndis_msg_class, rndis_recv, + TP_PROTO(const struct net_device *ndev, u16 q, + const struct rndis_message *msg), + TP_ARGS(ndev, q, msg) +); + +TRACE_DEFINE_ENUM(NVSP_MSG_TYPE_INIT); +TRACE_DEFINE_ENUM(NVSP_MSG_TYPE_INIT_COMPLETE); +TRACE_DEFINE_ENUM(NVSP_MSG1_TYPE_SEND_NDIS_VER); +TRACE_DEFINE_ENUM(NVSP_MSG1_TYPE_SEND_RECV_BUF); +TRACE_DEFINE_ENUM(NVSP_MSG1_TYPE_SEND_RECV_BUF_COMPLETE); +TRACE_DEFINE_ENUM(NVSP_MSG1_TYPE_REVOKE_RECV_BUF); +TRACE_DEFINE_ENUM(NVSP_MSG1_TYPE_SEND_SEND_BUF); +TRACE_DEFINE_ENUM(NVSP_MSG1_TYPE_SEND_SEND_BUF_COMPLETE); +TRACE_DEFINE_ENUM(NVSP_MSG1_TYPE_REVOKE_SEND_BUF); +TRACE_DEFINE_ENUM(NVSP_MSG1_TYPE_SEND_RNDIS_PKT); +TRACE_DEFINE_ENUM(NVSP_MSG1_TYPE_SEND_RNDIS_PKT_COMPLETE); +TRACE_DEFINE_ENUM(NVSP_MSG2_TYPE_SEND_NDIS_CONFIG); + +TRACE_DEFINE_ENUM(NVSP_MSG4_TYPE_SEND_VF_ASSOCIATION); +TRACE_DEFINE_ENUM(NVSP_MSG4_TYPE_SWITCH_DATA_PATH); + +TRACE_DEFINE_ENUM(NVSP_MSG5_TYPE_SUBCHANNEL); +TRACE_DEFINE_ENUM(NVSP_MSG5_TYPE_SEND_INDIRECTION_TABLE); + +#define show_nvsp_type(type) \ + __print_symbolic(type, \ + { NVSP_MSG_TYPE_INIT, "INIT" }, \ + { NVSP_MSG_TYPE_INIT_COMPLETE, "INIT_COMPLETE" }, \ + { NVSP_MSG1_TYPE_SEND_NDIS_VER, "SEND_NDIS_VER" }, \ + { NVSP_MSG1_TYPE_SEND_RECV_BUF, "SEND_RECV_BUF" }, \ + { NVSP_MSG1_TYPE_SEND_RECV_BUF_COMPLETE, "SEND_RECV_BUF_COMPLETE" }, \ + { NVSP_MSG1_TYPE_REVOKE_RECV_BUF, "REVOKE_RECV_BUF" }, \ + { NVSP_MSG1_TYPE_SEND_SEND_BUF, "SEND_SEND_BUF" }, \ + { NVSP_MSG1_TYPE_SEND_SEND_BUF_COMPLETE, "SEND_SEND_BUF_COMPLETE" }, \ + { NVSP_MSG1_TYPE_REVOKE_SEND_BUF, "REVOKE_SEND_BUF" }, \ + { NVSP_MSG1_TYPE_SEND_RNDIS_PKT, "SEND_RNDIS_PKT" }, \ + { NVSP_MSG1_TYPE_SEND_RNDIS_PKT_COMPLETE, "SEND_RNDIS_PKT_COMPLETE" },\ + { NVSP_MSG2_TYPE_SEND_NDIS_CONFIG, "SEND_NDIS_CONFIG" }, \ + { NVSP_MSG4_TYPE_SEND_VF_ASSOCIATION, "SEND_VF_ASSOCIATION" }, \ + { NVSP_MSG4_TYPE_SWITCH_DATA_PATH, "SWITCH_DATA_PATH" }, \ + { NVSP_MSG5_TYPE_SUBCHANNEL, "SUBCHANNEL" }, \ + { NVSP_MSG5_TYPE_SEND_INDIRECTION_TABLE, "SEND_INDIRECTION_TABLE" }) + +TRACE_EVENT(nvsp_send, + TP_PROTO(const struct net_device *ndev, + const struct nvsp_message *msg), + TP_ARGS(ndev, msg), + TP_STRUCT__entry( + __string( name, ndev->name ) + __field( u32, msg_type ) + ), + TP_fast_assign( + __assign_str(name, ndev->name); + __entry->msg_type = msg->hdr.msg_type; + ), + TP_printk("dev=%s type=%s", + __get_str(name), + show_nvsp_type(__entry->msg_type)) +); + +TRACE_EVENT(nvsp_send_pkt, + TP_PROTO(const struct net_device *ndev, + const struct vmbus_channel *chan, + const struct nvsp_1_message_send_rndis_packet *rpkt), + TP_ARGS(ndev, chan, rpkt), + TP_STRUCT__entry( + __string( name, ndev->name ) + __field( u16, qid ) + __field( u32, channel_type ) + __field( u32, section_index ) + __field( u32, section_size ) + ), + TP_fast_assign( + __assign_str(name, ndev->name); + __entry->qid = chan->offermsg.offer.sub_channel_index; + __entry->channel_type = rpkt->channel_type; + __entry->section_index = rpkt->send_buf_section_index; + __entry->section_size = rpkt->send_buf_section_size; + ), + TP_printk("dev=%s qid=%u type=%s section=%u size=%d", + __get_str(name), __entry->qid, + __entry->channel_type ? "CONTROL" : "DATA", + __entry->section_index, __entry->section_size) +); + +TRACE_EVENT(nvsp_recv, + TP_PROTO(const struct net_device *ndev, + const struct vmbus_channel *chan, + const struct nvsp_message *msg), + TP_ARGS(ndev, chan, msg), + TP_STRUCT__entry( + __string( name, ndev->name ) + __field( u16, qid ) + __field( u32, msg_type ) + ), + TP_fast_assign( + __assign_str(name, ndev->name); + __entry->qid = chan->offermsg.offer.sub_channel_index; + __entry->msg_type = msg->hdr.msg_type; + ), + TP_printk("dev=%s qid=%u type=%s", + __get_str(name), __entry->qid, + show_nvsp_type(__entry->msg_type)) +); + +#endif /* _NETVSC_TRACE_H */ + +/* This part must be outside protection */ +#undef TRACE_INCLUDE_PATH +#define TRACE_INCLUDE_PATH ../../drivers/net/hyperv +#include diff --git a/drivers/net/hyperv/rndis_filter.c b/drivers/net/hyperv/rndis_filter.c index 668680abaffb..2dc00f714482 100644 --- a/drivers/net/hyperv/rndis_filter.c +++ b/drivers/net/hyperv/rndis_filter.c @@ -31,6 +31,7 @@ #include #include "hyperv_net.h" +#include "netvsc_trace.h" static void rndis_set_multicast(struct work_struct *w); @@ -241,6 +242,8 @@ static int rndis_filter_send_request(struct rndis_device *dev, pb[0].len; } + trace_rndis_send(dev->ndev, 0, &req->request_msg); + rcu_read_lock_bh(); ret = netvsc_send(dev->ndev, packet, NULL, pb, NULL); rcu_read_unlock_bh(); @@ -1087,6 +1090,8 @@ void rndis_set_subchannel(struct work_struct *w) init_packet->msg.v5_msg.subchn_req.op = NVSP_SUBCHANNEL_ALLOCATE; init_packet->msg.v5_msg.subchn_req.num_subchannels = nvdev->num_chn - 1; + trace_nvsp_send(ndev, init_packet); + ret = vmbus_sendpacket(hv_dev->channel, init_packet, sizeof(struct nvsp_message), (unsigned long)init_packet,