From: Tim Sell <Timothy.Sell@xxxxxxxxxx>
Add error message to genuine rare error paths, and debug messages
to enable relatively non-verbose tracing of code paths
You can enable debug messages by including this on the kernel command line:
visornic.dyndbg=+p
or by this from the command line:
echo "module visornic +p" > <debugfs>/dynamic_debug/control
Refer to Documentation/dynamic-debug-howto.txt for more details.
In addition to the new debug and error messages, a message like the
following will be logged every time a visornic device is probed, which
will enable you to map back-and-forth between visorbus device names
(e.g., "vbus2:dev0") and netdev names (e.g., "eth0"):
visornic vbus2:dev0: visornic_probe success netdev=eth0
With this patch and visornic debugging enabled, you should expect to see
messages like the following in the most-common scenarios:
* driver loaded:
visornic_init
* device probed:
visornic vbus2:dev0: visornic_probe
visor_thread_start
visor_thread_start success
* network interface configured (ifconfig):
net eth0: visornic_open
net eth0: visornic_enable_with_timeout
net eth0: visornic_enable_with_timeout success
net eth0: visornic_open success
staging: unisys: More comments from Jes
Signed-off-by: Tim Sell <Timothy.Sell@xxxxxxxxxx>
Signed-off-by: David Kershner <david.kershner@xxxxxxxxxx>
Signed-off-by: Benjamin Romer <benjamin.romer@xxxxxxxxxx>
---
drivers/staging/unisys/visornic/visornic_main.c | 127 ++++++++++++++++++++++--
1 file changed, 116 insertions(+), 11 deletions(-)
diff --git a/drivers/staging/unisys/visornic/visornic_main.c b/drivers/staging/unisys/visornic/visornic_main.c
index 7100744..7b9821c 100644
--- a/drivers/staging/unisys/visornic/visornic_main.c
+++ b/drivers/staging/unisys/visornic/visornic_main.c
@@ -294,14 +294,18 @@ static int visor_thread_start(struct visor_thread_info *thrinfo,
int (*threadfn)(void *),
void *thrcontext, char *name)
{
+ pr_debug("%s\n", __func__);
/* used to stop the thread */
init_completion(&thrinfo->has_stopped);
thrinfo->task = kthread_run(threadfn, thrcontext, name);
if (IS_ERR(thrinfo->task)) {
+ pr_debug("%s failed (%ld)\n",
+ __func__, PTR_ERR(thrinfo->task));
thrinfo->id = 0;
return -EINVAL;
}
thrinfo->id = thrinfo->task->pid;
+ pr_debug("%s success\n", __func__);
return 0;
}
@@ -317,10 +321,12 @@ static void visor_thread_stop(struct visor_thread_info *thrinfo)
if (!thrinfo->id)
return; /* thread not running */
+ pr_debug("%s\n", __func__);
kthread_stop(thrinfo->task);
/* give up if the thread has NOT died in 1 minute */
if (wait_for_completion_timeout(&thrinfo->has_stopped, 60 * HZ))
thrinfo->id = 0;
+ pr_debug("%s success\n", __func__);
}
/* DebugFS code */
@@ -333,6 +339,7 @@ static ssize_t info_debugfs_read(struct file *file, char __user *buf,
struct visornic_devdata *devdata;
char *vbuf;
+ pr_debug("%s\n", __func__);
if (len > MAX_BUF)
len = MAX_BUF;
vbuf = kzalloc(len, GFP_KERNEL);
@@ -465,6 +472,8 @@ static ssize_t info_debugfs_read(struct file *file, char __user *buf,
}
bytes_read = simple_read_from_buffer(buf, len, offset, vbuf, str_pos);
kfree(vbuf);
+ pr_debug("%s success %ld\n",
+ __func__, (long)bytes_read);
return bytes_read;
}
@@ -520,6 +529,8 @@ visornic_serverdown_complete(struct work_struct *work)
serverdown_completion);
netdev = devdata->netdev;
+ dev_dbg(&netdev->dev, "%s\n", __func__);
+
/* Stop using datachan */
visor_thread_stop(&devdata->threadinfo);
@@ -547,6 +558,7 @@ visornic_serverdown_complete(struct work_struct *work)
devdata->server_down = true;
devdata->server_change_state = false;
+ dev_dbg(&netdev->dev, "%s success\n", __func__);
}
/**
@@ -560,13 +572,17 @@ visornic_serverdown_complete(struct work_struct *work)
static int
visornic_serverdown(struct visornic_devdata *devdata)
{
+ dev_dbg(&devdata->dev->device, "%s\n", __func__);
if (!devdata->server_down && !devdata->server_change_state) {
devdata->server_change_state = true;
queue_work(visornic_serverdown_workqueue,
&devdata->serverdown_completion);
} else if (devdata->server_change_state) {
+ dev_dbg(&devdata->dev->device, "%s changing state\n",
+ __func__);
return -EINVAL;
}
+ dev_dbg(&devdata->dev->device, "%s success\n", __func__);
return 0;
}
@@ -676,6 +692,8 @@ visornic_disable_with_timeout(struct net_device *netdev, const int timeout)
unsigned long flags;
int wait = 0;
+ dev_dbg(&netdev->dev, "%s\n", __func__);
+
/* stop the transmit queue so nothing more can be transmitted */
netif_stop_queue(netdev);
@@ -701,6 +719,8 @@ visornic_disable_with_timeout(struct net_device *netdev, const int timeout)
break;
if (devdata->server_down || devdata->server_change_state) {
spin_unlock_irqrestore(&devdata->priv_lock, flags);
+ dev_dbg(&netdev->dev, "%s server went away\n",
+ __func__);
return -EIO;
}
set_current_state(TASK_INTERRUPTIBLE);
@@ -743,6 +763,7 @@ visornic_disable_with_timeout(struct net_device *netdev, const int timeout)
break;
}
+ dev_dbg(&netdev->dev, "%s success\n", __func__);
return 0;
}
@@ -810,12 +831,17 @@ visornic_enable_with_timeout(struct net_device *netdev, const int timeout)
unsigned long flags;
int wait = 0;
+ dev_dbg(&netdev->dev, "%s\n", __func__);
+
/* NOTE: the other end automatically unposts the rcv buffers when it
* gets a disable.
*/
i = init_rcv_bufs(netdev, devdata);
- if (i < 0)
+ if (i < 0) {
+ dev_err(&netdev->dev,
+ "%s failed to init rcv bufs (%d)\n", __func__, i);
return i;
+ }
spin_lock_irqsave(&devdata->priv_lock, flags);
devdata->enabled = 1;
@@ -838,6 +864,8 @@ visornic_enable_with_timeout(struct net_device *netdev, const int timeout)
break;
if (devdata->server_down || devdata->server_change_state) {
spin_unlock_irqrestore(&devdata->priv_lock, flags);
+ dev_dbg(&netdev->dev, "%s server went away\n",
+ __func__);
return -EIO;
}
set_current_state(TASK_INTERRUPTIBLE);
@@ -848,8 +876,10 @@ visornic_enable_with_timeout(struct net_device *netdev, const int timeout)
spin_unlock_irqrestore(&devdata->priv_lock, flags);
- if (!devdata->enab_dis_acked)
+ if (!devdata->enab_dis_acked) {
+ dev_err(&netdev->dev, "%s missing ACK\n", __func__);
return -EIO;
+ }
/* find an open slot in the array to save off VisorNic references
* for debug
@@ -861,6 +891,7 @@ visornic_enable_with_timeout(struct net_device *netdev, const int timeout)
}
}
+ dev_dbg(&netdev->dev, "%s success\n", __func__);
return 0;
}
@@ -882,6 +913,7 @@ visornic_timeout_reset(struct work_struct *work)
devdata = container_of(work, struct visornic_devdata, timeout_reset);
netdev = devdata->netdev;
+ dev_dbg(&netdev->dev, "%s\n", __func__);
netif_stop_queue(netdev);
response = visornic_disable_with_timeout(netdev, 100);
if (response)
@@ -896,6 +928,7 @@ visornic_timeout_reset(struct work_struct *work)
call_serverdown:
visornic_serverdown(devdata);
+ dev_dbg(&netdev->dev, "%s success\n", __func__);
}
/**
@@ -908,6 +941,7 @@ call_serverdown:
static int
visornic_open(struct net_device *netdev)
{
+ dev_dbg(&netdev->dev, "%s\n", __func__);
visornic_enable_with_timeout(netdev, VISORNIC_INFINITE_RESPONSE_WAIT);
/* start the interface's transmit queue, allowing it to accept
@@ -915,6 +949,7 @@ visornic_open(struct net_device *netdev)
*/
netif_start_queue(netdev);
+ dev_dbg(&netdev->dev, "%s success\n", __func__);
return 0;
}
@@ -928,9 +963,11 @@ visornic_open(struct net_device *netdev)
static int
visornic_close(struct net_device *netdev)
{
+ dev_dbg(&netdev->dev, "%s\n", __func__);
netif_stop_queue(netdev);
visornic_disable_with_timeout(netdev, VISORNIC_INFINITE_RESPONSE_WAIT);
+ dev_dbg(&netdev->dev, "%s success\n", __func__);
return 0;
}
@@ -961,6 +998,8 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
devdata->server_change_state) {
spin_unlock_irqrestore(&devdata->priv_lock, flags);
devdata->busy_cnt++;
+ dev_dbg(&netdev->dev,
+ "%s busy - queue stopped\n", __func__);
return NETDEV_TX_BUSY;
}
@@ -979,6 +1018,9 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
if (firstfraglen < ETH_HEADER_SIZE) {
spin_unlock_irqrestore(&devdata->priv_lock, flags);
devdata->busy_cnt++;
+ dev_err(&netdev->dev,
+ "%s busy - first frag too small (%d)\n",
+ __func__, firstfraglen);
return NETDEV_TX_BUSY;
}
@@ -1018,6 +1060,9 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
netif_stop_queue(netdev);
spin_unlock_irqrestore(&devdata->priv_lock, flags);
devdata->busy_cnt++;
+ dev_dbg(&netdev->dev,
+ "%s busy - waiting for iovm to catch up\n",
+ __func__);
return NETDEV_TX_BUSY;
}
if (devdata->queuefullmsg_logged)
@@ -1058,6 +1103,8 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
if (cmdrsp->net.xmt.num_frags == -1) {
spin_unlock_irqrestore(&devdata->priv_lock, flags);
devdata->busy_cnt++;
+ dev_err(&netdev->dev,
+ "%s busy - copy frags failed\n", __func__);
return NETDEV_TX_BUSY;
}
@@ -1066,6 +1113,8 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
netif_stop_queue(netdev);
spin_unlock_irqrestore(&devdata->priv_lock, flags);
devdata->busy_cnt++;
+ dev_dbg(&netdev->dev,
+ "%s busy - signalinsert failed\n", __func__);
return NETDEV_TX_BUSY;
}
@@ -1098,6 +1147,9 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
* netif_wake_queue() after lower
* threshold
*/
+ dev_dbg(&netdev->dev,
+ "%s busy - invoking iovm flow control\n",
+ __func__);
devdata->flow_control_upper_hits++;
}
spin_unlock_irqrestore(&devdata->priv_lock, flags);
@@ -1200,16 +1252,20 @@ visornic_xmit_timeout(struct net_device *netdev)
struct visornic_devdata *devdata = netdev_priv(netdev);
unsigned long flags;
+ dev_dbg(&netdev->dev, "%s\n", __func__);
spin_lock_irqsave(&devdata->priv_lock, flags);
/* Ensure that a ServerDown message hasn't been received */
if (!devdata->enabled ||
(devdata->server_down && !devdata->server_change_state)) {
+ dev_dbg(&netdev->dev, "%s no processing\n",
+ __func__);
spin_unlock_irqrestore(&devdata->priv_lock, flags);
return;
}
spin_unlock_irqrestore(&devdata->priv_lock, flags);
queue_work(visornic_timeout_reset_workqueue, &devdata->timeout_reset);
+ dev_dbg(&netdev->dev, "%s success\n", __func__);
}
/**
@@ -1800,9 +1856,13 @@ static int visornic_probe(struct visor_device *dev)
int channel_offset = 0;
u64 features;
+ dev_dbg(&dev->device, "%s\n", __func__);
netdev = alloc_etherdev(sizeof(struct visornic_devdata));
- if (!netdev)
+ if (!netdev) {
+ dev_err(&dev->device,
+ "%s alloc_etherdev failed\n", __func__);
return -ENOMEM;
+ }
netdev->netdev_ops = &visornic_dev_ops;
netdev->watchdog_timeo = (5 * HZ);
@@ -1814,11 +1874,17 @@ static int visornic_probe(struct visor_device *dev)
vnic.macaddr);
err = visorbus_read_channel(dev, channel_offset, netdev->dev_addr,
ETH_ALEN);
- if (err < 0)
+ if (err < 0) {
+ dev_err(&dev->device,
+ "%s failed to get mac addr from chan (%d)\n",
+ __func__, err);
goto cleanup_netdev;
+ }
devdata = devdata_initialize(netdev_priv(netdev), dev);
if (!devdata) {
+ dev_err(&dev->device,
+ "%s devdata_initialize failed\n", __func__);
err = -ENOMEM;
goto cleanup_netdev;
}
@@ -1834,8 +1900,12 @@ static int visornic_probe(struct visor_device *dev)
vnic.num_rcv_bufs);
err = visorbus_read_channel(dev, channel_offset,
&devdata->num_rcv_bufs, 4);
- if (err)
+ if (err) {
+ dev_err(&dev->device,
+ "%s failed to get #rcv bufs from chan (%d)\n",
+ __func__, err);
goto cleanup_netdev;
+ }
devdata->rcvbuf = kmalloc(sizeof(struct sk_buff *) *
devdata->num_rcv_bufs, GFP_KERNEL);
@@ -1876,38 +1946,58 @@ static int visornic_probe(struct visor_device *dev)
channel_offset = offsetof(struct spar_io_channel_protocol,
vnic.mtu);
err = visorbus_read_channel(dev, channel_offset, &netdev->mtu, 4);
- if (err)
+ if (err) {
+ dev_err(&dev->device,
+ "%s failed to get mtu from chan (%d)\n",
+ __func__, err);
goto cleanup_xmit_cmdrsp;
+ }
/* TODO: Setup Interrupt information */
/* Let's start our threads to get responses */
channel_offset = offsetof(struct spar_io_channel_protocol,
channel_header.features);
err = visorbus_read_channel(dev, channel_offset, &features, 8);
- if (err)
+ if (err) {
+ dev_err(&dev->device,
+ "%s failed to get features from chan (%d)\n",
+ __func__, err);
goto cleanup_xmit_cmdrsp;
+ }
features |= ULTRA_IO_CHANNEL_IS_POLLING;
err = visorbus_write_channel(dev, channel_offset, &features, 8);
- if (err)
+ if (err) {
+ dev_err(&dev->device,
+ "%s failed to set features in chan (%d)\n",
+ __func__, err);
goto cleanup_xmit_cmdrsp;
+ }
devdata->thread_wait_ms = 2;
visor_thread_start(&devdata->threadinfo, process_incoming_rsps,
devdata, "vnic_incoming");
err = register_netdev(netdev);
- if (err)
+ if (err) {
+ dev_err(&dev->device,
+ "%s register_netdev failed (%d)\n", __func__, err);
goto cleanup_thread_stop;
+ }
/* create debgug/sysfs directories */
devdata->eth_debugfs_dir = debugfs_create_dir(netdev->name,
visornic_debugfs_dir);
if (!devdata->eth_debugfs_dir) {
+ dev_err(&dev->device,
+ "%s debugfs_create_dir %s failed\n",
+ __func__, netdev->name);
err = -ENOMEM;
goto cleanup_thread_stop;
}
+ dev_info(&dev->device, "%s success netdev=%s\n",
+ __func__, netdev->name);
return 0;
cleanup_thread_stop:
@@ -1955,8 +2045,11 @@ static void visornic_remove(struct visor_device *dev)
{
struct visornic_devdata *devdata = dev_get_drvdata(&dev->device);
- if (!devdata)
+ if (!devdata) {
+ dev_err(&dev->device, "%s no devdata\n", __func__);
return;
+ }
+ dev_dbg(&dev->device, "%s\n", __func__);
dev_set_drvdata(&dev->device, NULL);
host_side_disappeared(devdata);
kref_put(&devdata->kref, devdata_release);
@@ -1980,8 +2073,10 @@ static int visornic_pause(struct visor_device *dev,
{
struct visornic_devdata *devdata = dev_get_drvdata(&dev->device);
+ dev_dbg(&dev->device, "%s\n", __func__);
visornic_serverdown(devdata);
complete_func(dev, 0);
+ dev_dbg(&dev->device, "%s success\n", __func__);
return 0;
}
@@ -2003,10 +2098,13 @@ static int visornic_resume(struct visor_device *dev,
unsigned long flags;
devdata = dev_get_drvdata(&dev->device);
- if (!devdata)
+ if (!devdata) {
+ dev_err(&dev->device, "%s no devdata\n", __func__);
return -EINVAL;
+ }
netdev = devdata->netdev;
+ dev_dbg(&dev->device, "%s\n", __func__);
if (devdata->server_down && !devdata->server_change_state) {
devdata->server_change_state = true;
@@ -2032,10 +2130,13 @@ static int visornic_resume(struct visor_device *dev,
*/
send_enbdis(netdev, 1, devdata);
} else if (devdata->server_change_state) {
+ dev_err(&dev->device, "%s server_change_state\n",
+ __func__);
return -EIO;
}
complete_func(dev, 0);
+ dev_dbg(&dev->device, "%s success\n", __func__);
return 0;
}
@@ -2051,6 +2152,8 @@ static int visornic_init(void)
struct dentry *ret;
int err = -ENOMEM;
+ pr_debug("%s\n", __func__);
+
/* create workqueue for serverdown completion */
visornic_serverdown_workqueue =
create_singlethread_workqueue("visornic_serverdown");
@@ -2116,6 +2219,8 @@ cleanup_debugfs:
*/
static void visornic_cleanup(void)
{
+ pr_debug("%s\n", __func__);
+
if (visornic_serverdown_workqueue) {
flush_workqueue(visornic_serverdown_workqueue);
destroy_workqueue(visornic_serverdown_workqueue);
--
2.1.4
_______________________________________________
devel mailing list
devel@xxxxxxxxxxxxxxxxxxxxxx
http://driverdev.linuxdriverproject.org/mailman/listinfo/driverdev-devel
