2012-02-18 20:58:41

by Stefan Richter

[permalink] [raw]
Subject: [PATCH 0/4] firewire, some more logging related patches

Forthcoming:
* firewire: sbp2: identify to driver core as "firewire_sbp2", not "sbp2"
* firewire: net: identify to driver core as "firewire_net", not "net"
* firewire: net: prefix all log messages with interface name
* firewire: core: prefix log messages with card name

drivers/firewire/core-card.c | 28 ++++++++++---
drivers/firewire/core-cdev.c | 10 ++--
drivers/firewire/core-device.c | 60 +++++++++++++---------------
drivers/firewire/core-topology.c | 18 ++++----
drivers/firewire/core-transaction.c | 4 -
drivers/firewire/core.h | 6 ++
drivers/firewire/net.c | 45 ++++++++++++---------
drivers/firewire/sbp2.c | 6 --
include/linux/firewire.h | 3 -
9 files changed, 100 insertions(+), 80 deletions(-)
--
Stefan Richter
-=====-===-- --=- =--=-
http://arcgraph.de/sr/


2012-02-18 21:01:26

by Stefan Richter

[permalink] [raw]
Subject: [PATCH 1/4] firewire: sbp2: identify to driver core as "firewire_sbp2", not "sbp2"

Commit eba9ebaaa26d "firewire: sbp2: use dev_printk API" changed
messages from e.g.
firewire_sbp2: fw3.0: logged in to LUN 0000 (0 retries)
to
sbp2 fw3.0: logged in to LUN 0000 (0 retries)
because the driver calls itself as "sbp2" when registering with driver
core and with SCSI core. This is of course confusing, so switch to the
name "firewire_sbp2" for driver core in order to match what lsmod and
/sys/module/ show. So we are back to
firewire_sbp2 fw3.0: logged in to LUN 0000 (0 retries)
in the kernel log.

This also changes
/sys/bus/firewire/drivers/sbp2
/sys/bus/firewire/devices/fw3.0/driver -> [...]/sbp2
/sys/module/firewire_sbp2/drivers/firewire:sbp2
to
/sys/bus/firewire/drivers/firewire_sbp2
/sys/bus/firewire/devices/fw3.0/driver -> [...]/firewire_sbp2
/sys/module/firewire_sbp2/drivers/firewire:firewire_sbp2

but "cat /sys/class/scsi_host/host27/proc_name" stays "sbp2" just in
case that proc_name is used by any userland.

The transport detection in lsscsi is not affected. (Tested with lsscsi
version 0.25.) Udev's /dev/disk/by-id and by-path symlinks are not
affected either.

Signed-off-by: Stefan Richter <[email protected]>
---
drivers/firewire/sbp2.c | 6 ++----
1 file changed, 2 insertions(+), 4 deletions(-)

--- a/drivers/firewire/sbp2.c
+++ b/drivers/firewire/sbp2.c
@@ -125,8 +125,6 @@ MODULE_PARM_DESC(workarounds, "Work arou
", override internal blacklist = " __stringify(SBP2_WORKAROUND_OVERRIDE)
", or a combination)");

-static const char sbp2_driver_name[] = "sbp2";
-
/*
* We create one struct sbp2_logical_unit per SBP-2 Logical Unit Number Entry
* and one struct scsi_device per sbp2_logical_unit.
@@ -1270,7 +1268,7 @@ static const struct ieee1394_device_id s
static struct fw_driver sbp2_driver = {
.driver = {
.owner = THIS_MODULE,
- .name = sbp2_driver_name,
+ .name = KBUILD_MODNAME,
.bus = &fw_bus_type,
.probe = sbp2_probe,
.remove = sbp2_remove,
@@ -1599,7 +1597,7 @@ static struct device_attribute *sbp2_scs
static struct scsi_host_template scsi_driver_template = {
.module = THIS_MODULE,
.name = "SBP-2 IEEE-1394",
- .proc_name = sbp2_driver_name,
+ .proc_name = "sbp2",
.queuecommand = sbp2_scsi_queuecommand,
.slave_alloc = sbp2_scsi_slave_alloc,
.slave_configure = sbp2_scsi_slave_configure,


--
Stefan Richter
-=====-===-- --=- =--=-
http://arcgraph.de/sr/

2012-02-18 21:02:07

by Stefan Richter

[permalink] [raw]
Subject: [PATCH 2/4] firewire: net: identify to driver core as "firewire_net", not "net"

On second thought, there is little reason to have driver name differ
from module name. Therefore, change
/sys/bus/firewire/drivers/net
/sys/bus/firewire/devices/fw0.0/driver -> [...]/net
/sys/module/firewire_net/drivers/firewire:net
to
/sys/bus/firewire/drivers/firewire_net
/sys/bus/firewire/devices/fw0.0/driver -> [...]/firewire_net
/sys/module/firewire_net/drivers/firewire:firewire_net
It is redundant but consistent with firewire-sbp2's recently changed
driver name.

I don't see this anywhere used, so it should not matter either way.

Signed-off-by: Stefan Richter <[email protected]>
---
drivers/firewire/net.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

--- a/drivers/firewire/net.c
+++ b/drivers/firewire/net.c
@@ -1648,7 +1648,7 @@ static const struct ieee1394_device_id f
static struct fw_driver fwnet_driver = {
.driver = {
.owner = THIS_MODULE,
- .name = "net",
+ .name = KBUILD_MODNAME,
.bus = &fw_bus_type,
.probe = fwnet_probe,
.remove = fwnet_remove,


--
Stefan Richter
-=====-===-- --=- =--=-
http://arcgraph.de/sr/

2012-02-18 21:02:44

by Stefan Richter

[permalink] [raw]
Subject: [PATCH 3/4] firewire: net: prefix all log messages with interface name

Change the log line prefix from "firewire_net: " to
"firewire_net firewire0: " etc. for the case that several RFC 2734
interfaces are being used in the same machine. Despite this addition,
module size is a little bit decreased because KBUILD_MODNAME is now
moved from the format strings into a %s argument.

Note, the kernel's stock functions are not very useful to firewire-net:

dev_notice(&net->dev, "abc\n"); -> net firewire0: abc
netdev_notice(net, "abc\n"); -> firewire_ohci 0000:0a:00.0: firewire0: abc

Nor would be a dev_printk on the fw_unit.device to which firewire-net is
being bound, because there are generally multiple ones of those per
interface (from all RFC 2734 peers on the bus, the local node being only
one of them).

In the initialization message of each interface, log the PCI device
name of the card which is parent of the netdevice instead of the GUID
of the peer which was semi-randomly used to establish the netdevice.

Signed-off-by: Stefan Richter <[email protected]>
---
drivers/firewire/net.c | 43 ++++++++++++++++++++++++-----------------
1 file changed, 25 insertions(+), 18 deletions(-)

--- a/drivers/firewire/net.c
+++ b/drivers/firewire/net.c
@@ -29,6 +29,11 @@
#include <asm/unaligned.h>
#include <net/arp.h>

+#define fwnet_notice(net, fmt, args...) \
+ printk(KERN_NOTICE "%s %s: " fmt, KBUILD_MODNAME, (net)->name, ## args)
+#define fwnet_err(net, fmt, args...) \
+ printk(KERN_ERR "%s %s: " fmt, KBUILD_MODNAME, (net)->name, ## args)
+
/* rx limits */
#define FWNET_MAX_FRAGMENTS 30 /* arbitrary, > TX queue depth */
#define FWNET_ISO_PAGE_COUNT (PAGE_SIZE < 16*1024 ? 4 : 2)
@@ -256,8 +261,8 @@ static int fwnet_header_rebuild(struct s
if (get_unaligned_be16(&h->h_proto) == ETH_P_IP)
return arp_find((unsigned char *)&h->h_dest, skb);

- fw_notify("%s: unable to resolve type %04x addresses\n",
- skb->dev->name, be16_to_cpu(h->h_proto));
+ fwnet_notice(skb->dev, "unable to resolve type %04x addresses\n",
+ be16_to_cpu(h->h_proto));
return 0;
}

@@ -369,7 +374,7 @@ static struct fwnet_fragment_info *fwnet

new = kmalloc(sizeof(*new), GFP_ATOMIC);
if (!new) {
- fw_error("out of memory\n");
+ fwnet_err(pd->skb->dev, "out of memory\n");
return NULL;
}

@@ -414,7 +419,7 @@ fail_w_fi:
fail_w_new:
kfree(new);
fail:
- fw_error("out of memory\n");
+ fwnet_err(net, "out of memory\n");

return NULL;
}
@@ -554,7 +559,7 @@ static int fwnet_finish_incoming_packet(
sspd = arp1394->sspd;
/* Sanity check. OS X 10.3 PPC reportedly sends 131. */
if (sspd > SCODE_3200) {
- fw_notify("sspd %x out of range\n", sspd);
+ fwnet_notice(net, "sspd %x out of range\n", sspd);
sspd = SCODE_3200;
}
max_payload = fwnet_max_payload(arp1394->max_rec, sspd);
@@ -574,8 +579,8 @@ static int fwnet_finish_incoming_packet(
spin_unlock_irqrestore(&dev->lock, flags);

if (!peer) {
- fw_notify("No peer for ARP packet from %016llx\n",
- (unsigned long long)peer_guid);
+ fwnet_notice(net, "no peer for ARP packet from %016llx\n",
+ (unsigned long long)peer_guid);
goto no_peer;
}

@@ -691,7 +696,7 @@ static int fwnet_incoming_packet(struct

skb = dev_alloc_skb(len + net->hard_header_len + 15);
if (unlikely(!skb)) {
- fw_error("out of memory\n");
+ fwnet_err(net, "out of memory\n");
net->stats.rx_dropped++;

return -ENOMEM;
@@ -814,7 +819,7 @@ static void fwnet_receive_packet(struct
rcode = RCODE_TYPE_ERROR;
else if (fwnet_incoming_packet(dev, payload, length,
source, generation, false) != 0) {
- fw_error("Incoming packet failure\n");
+ fwnet_err(dev->netdev, "incoming packet failure\n");
rcode = RCODE_CONFLICT_ERROR;
} else
rcode = RCODE_COMPLETE;
@@ -881,7 +886,7 @@ static void fwnet_receive_broadcast(stru
if (retval >= 0)
fw_iso_context_queue_flush(dev->broadcast_rcv_context);
else
- fw_error("requeue failed\n");
+ fwnet_err(dev->netdev, "requeue failed\n");
}

static struct kmem_cache *fwnet_packet_task_cache;
@@ -936,9 +941,10 @@ static void fwnet_transmit_packet_done(s
case RFC2374_HDR_LASTFRAG:
case RFC2374_HDR_UNFRAG:
default:
- fw_error("Outstanding packet %x lf %x, header %x,%x\n",
- ptask->outstanding_pkts, lf, ptask->hdr.w0,
- ptask->hdr.w1);
+ fwnet_err(dev->netdev,
+ "outstanding packet %x lf %x, header %x,%x\n",
+ ptask->outstanding_pkts, lf, ptask->hdr.w0,
+ ptask->hdr.w1);
BUG();

case RFC2374_HDR_FIRSTFRAG:
@@ -1010,8 +1016,9 @@ static void fwnet_write_complete(struct
fwnet_transmit_packet_failed(ptask);

if (printk_timed_ratelimit(&j, 1000) || rcode != last_rcode) {
- fw_error("fwnet_write_complete: "
- "failed: %x (skipped %d)\n", rcode, errors_skipped);
+ fwnet_err(ptask->dev->netdev,
+ "fwnet_write_complete failed: %x (skipped %d)\n",
+ rcode, errors_skipped);

errors_skipped = 0;
last_rcode = rcode;
@@ -1540,13 +1547,13 @@ static int fwnet_probe(struct device *_d
put_unaligned_be64(~0ULL, net->broadcast);
ret = register_netdev(net);
if (ret) {
- fw_error("Cannot register the driver\n");
+ fwnet_err(net, "cannot register the driver\n");
goto out;
}

list_add_tail(&dev->dev_link, &fwnet_device_list);
- fw_notify("%s: IPv4 over FireWire on device %016llx\n",
- net->name, (unsigned long long)card->guid);
+ fwnet_notice(net, "IPv4 over FireWire on card %s\n",
+ dev_name(card->device));
have_dev:
ret = fwnet_add_peer(dev, unit, device);
if (ret && allocated_netdev) {


--
Stefan Richter
-=====-===-- --=- =--=-
http://arcgraph.de/sr/

2012-02-18 21:03:32

by Stefan Richter

[permalink] [raw]
Subject: [PATCH 4/4] firewire: core: prefix log messages with card name

Associate all log messages from firewire-core with the respective card
because some people have more than one card. E.g.
firewire_ohci 0000:04:00.0: added OHCI v1.10 device as card 0, 8 IR + 8 IT contexts, quirks 0x0
firewire_ohci 0000:05:00.0: added OHCI v1.10 device as card 1, 8 IR + 8 IT contexts, quirks 0x0
firewire_core: created device fw0: GUID 0814438400000389, S800
firewire_core: phy config: new root=ffc1, gap_count=5
firewire_core: created device fw1: GUID 0814438400000388, S800
firewire_core: created device fw2: GUID 0001d202e06800d1, S800
turns into
firewire_ohci 0000:04:00.0: added OHCI v1.10 device as card 0, 8 IR + 8 IT contexts, quirks 0x0
firewire_ohci 0000:05:00.0: added OHCI v1.10 device as card 1, 8 IR + 8 IT contexts, quirks 0x0
firewire_core 0000:04:00.0: created device fw0: GUID 0814438400000389, S800
firewire_core 0000:04:00.0: phy config: new root=ffc1, gap_count=5
firewire_core 0000:05:00.0: created device fw1: GUID 0814438400000388, S800
firewire_core 0000:04:00.0: created device fw2: GUID 0001d202e06800d1, S800

This increases the module size slightly; to keep this in check, turn the
former printk wrapper macros into functions. Their implementation is
largely copied from driver core's dev_printk counterparts.

Signed-off-by: Stefan Richter <[email protected]>
---
drivers/firewire/core-card.c | 28 ++++++++++---
drivers/firewire/core-cdev.c | 10 ++--
drivers/firewire/core-device.c | 60 +++++++++++++---------------
drivers/firewire/core-topology.c | 18 ++++----
drivers/firewire/core-transaction.c | 4 +-
drivers/firewire/core.h | 6 +++
include/linux/firewire.h | 3 -
7 files changed, 72 insertions(+), 57 deletions(-)

--- a/drivers/firewire/core-card.c
+++ b/drivers/firewire/core-card.c
@@ -37,6 +37,22 @@

#include "core.h"

+#define define_fw_printk_level(func, kern_level) \
+void func(const struct fw_card *card, const char *fmt, ...) \
+{ \
+ struct va_format vaf; \
+ va_list args; \
+ \
+ va_start(args, fmt); \
+ vaf.fmt = fmt; \
+ vaf.va = &args; \
+ printk(kern_level KBUILD_MODNAME " %s: %pV", \
+ dev_name(card->device), &vaf); \
+ va_end(args); \
+}
+define_fw_printk_level(fw_err, KERN_ERR);
+define_fw_printk_level(fw_notice, KERN_NOTICE);
+
int fw_compute_block_crc(__be32 *block)
{
int length;
@@ -260,7 +276,7 @@ static void allocate_broadcast_channel(s
fw_iso_resource_manage(card, generation, 1ULL << 31,
&channel, &bandwidth, true);
if (channel != 31) {
- fw_notify("failed to allocate broadcast channel\n");
+ fw_notice(card, "failed to allocate broadcast channel\n");
return;
}
card->broadcast_channel_allocated = true;
@@ -343,14 +359,14 @@ static void bm_work(struct work_struct *

if (!card->irm_node->link_on) {
new_root_id = local_id;
- fw_notify("%s, making local node (%02x) root.\n",
+ fw_notice(card, "%s, making local node (%02x) root\n",
"IRM has link off", new_root_id);
goto pick_me;
}

if (irm_is_1394_1995_only && !keep_this_irm) {
new_root_id = local_id;
- fw_notify("%s, making local node (%02x) root.\n",
+ fw_notice(card, "%s, making local node (%02x) root\n",
"IRM is not 1394a compliant", new_root_id);
goto pick_me;
}
@@ -405,7 +421,7 @@ static void bm_work(struct work_struct *
* root, and thus, IRM.
*/
new_root_id = local_id;
- fw_notify("%s, making local node (%02x) root.\n",
+ fw_notice(card, "%s, making local node (%02x) root\n",
"BM lock failed", new_root_id);
goto pick_me;
}
@@ -478,8 +494,8 @@ static void bm_work(struct work_struct *
spin_unlock_irq(&card->lock);

if (do_reset) {
- fw_notify("phy config: card %d, new root=%x, gap_count=%d\n",
- card->index, new_root_id, gap_count);
+ fw_notice(card, "phy config: new root=%x, gap_count=%d\n",
+ new_root_id, gap_count);
fw_send_phy_config(card, new_root_id, generation, gap_count);
reset_bus(card, true);
/* Will allocate broadcast channel after the reset. */
--- a/drivers/firewire/core-cdev.c
+++ b/drivers/firewire/core-cdev.c
@@ -389,7 +389,7 @@ static void queue_bus_reset_event(struct

e = kzalloc(sizeof(*e), GFP_KERNEL);
if (e == NULL) {
- fw_notify("Out of memory when allocating event\n");
+ fw_notice(client->device->card, "out of memory when allocating event\n");
return;
}

@@ -691,7 +691,7 @@ static void handle_request(struct fw_car
r = kmalloc(sizeof(*r), GFP_ATOMIC);
e = kmalloc(sizeof(*e), GFP_ATOMIC);
if (r == NULL || e == NULL) {
- fw_notify("Out of memory when allocating event\n");
+ fw_notice(card, "out of memory when allocating event\n");
goto failed;
}
r->card = card;
@@ -928,7 +928,7 @@ static void iso_callback(struct fw_iso_c

e = kmalloc(sizeof(*e) + header_length, GFP_ATOMIC);
if (e == NULL) {
- fw_notify("Out of memory when allocating event\n");
+ fw_notice(context->card, "out of memory when allocating event\n");
return;
}
e->interrupt.type = FW_CDEV_EVENT_ISO_INTERRUPT;
@@ -948,7 +948,7 @@ static void iso_mc_callback(struct fw_is

e = kmalloc(sizeof(*e), GFP_ATOMIC);
if (e == NULL) {
- fw_notify("Out of memory when allocating event\n");
+ fw_notice(context->card, "out of memory when allocating event\n");
return;
}
e->interrupt.type = FW_CDEV_EVENT_ISO_INTERRUPT_MULTICHANNEL;
@@ -1548,7 +1548,7 @@ void fw_cdev_handle_phy_packet(struct fw
list_for_each_entry(client, &card->phy_receiver_list, phy_receiver_link) {
e = kmalloc(sizeof(*e) + 8, GFP_ATOMIC);
if (e == NULL) {
- fw_notify("Out of memory when allocating event\n");
+ fw_notice(card, "out of memory when allocating event\n");
break;
}
e->phy_packet.closure = client->phy_receiver_closure;
--- a/drivers/firewire/core-device.c
+++ b/drivers/firewire/core-device.c
@@ -485,6 +485,7 @@ static int read_rom(struct fw_device *de
*/
static int read_config_rom(struct fw_device *device, int generation)
{
+ struct fw_card *card = device->card;
const u32 *old_rom, *new_rom;
u32 *rom, *stack;
u32 sp, key;
@@ -529,12 +530,12 @@ static int read_config_rom(struct fw_dev
*/
if ((rom[2] & 0x7) < device->max_speed ||
device->max_speed == SCODE_BETA ||
- device->card->beta_repeaters_present) {
+ card->beta_repeaters_present) {
u32 dummy;

/* for S1600 and S3200 */
if (device->max_speed == SCODE_BETA)
- device->max_speed = device->card->link_speed;
+ device->max_speed = card->link_speed;

while (device->max_speed > SCODE_100) {
if (read_rom(device, generation, 0, &dummy) ==
@@ -576,9 +577,9 @@ static int read_config_rom(struct fw_dev
* a firmware bug. Ignore this whole block, i.e.
* simply set a fake block length of 0.
*/
- fw_error("skipped invalid ROM block %x at %llx\n",
- rom[i],
- i * 4 | CSR_REGISTER_BASE | CSR_CONFIG_ROM);
+ fw_err(card, "skipped invalid ROM block %x at %llx\n",
+ rom[i],
+ i * 4 | CSR_REGISTER_BASE | CSR_CONFIG_ROM);
rom[i] = 0;
end = i;
}
@@ -604,9 +605,10 @@ static int read_config_rom(struct fw_dev
* the ROM don't have to check offsets all the time.
*/
if (i + (rom[i] & 0xffffff) >= MAX_CONFIG_ROM_SIZE) {
- fw_error("skipped unsupported ROM entry %x at %llx\n",
- rom[i],
- i * 4 | CSR_REGISTER_BASE | CSR_CONFIG_ROM);
+ fw_err(card,
+ "skipped unsupported ROM entry %x at %llx\n",
+ rom[i],
+ i * 4 | CSR_REGISTER_BASE | CSR_CONFIG_ROM);
rom[i] = 0;
continue;
}
@@ -673,7 +675,7 @@ static void create_units(struct fw_devic
*/
unit = kzalloc(sizeof(*unit), GFP_KERNEL);
if (unit == NULL) {
- fw_error("failed to allocate memory for unit\n");
+ fw_err(device->card, "out of memory for unit\n");
continue;
}

@@ -875,7 +877,7 @@ static int lookup_existing_device(struct
smp_wmb(); /* update node_id before generation */
old->generation = card->generation;
old->config_rom_retries = 0;
- fw_notify("rediscovered device %s\n", dev_name(dev));
+ fw_notice(card, "rediscovered device %s\n", dev_name(dev));

PREPARE_DELAYED_WORK(&old->work, fw_device_update);
fw_schedule_device_work(old, 0);
@@ -956,6 +958,7 @@ static void fw_device_init(struct work_s
{
struct fw_device *device =
container_of(work, struct fw_device, work.work);
+ struct fw_card *card = device->card;
struct device *revived_dev;
int minor, ret;

@@ -972,16 +975,16 @@ static void fw_device_init(struct work_s
fw_schedule_device_work(device, RETRY_DELAY);
} else {
if (device->node->link_on)
- fw_notify("giving up on config rom for node id %x\n",
+ fw_notice(card, "giving up on Config ROM for node id %x\n",
device->node_id);
- if (device->node == device->card->root_node)
- fw_schedule_bm_work(device->card, 0);
+ if (device->node == card->root_node)
+ fw_schedule_bm_work(card, 0);
fw_device_release(&device->device);
}
return;
}

- revived_dev = device_find_child(device->card->device,
+ revived_dev = device_find_child(card->device,
device, lookup_existing_device);
if (revived_dev) {
put_device(revived_dev);
@@ -1004,7 +1007,7 @@ static void fw_device_init(struct work_s

device->device.bus = &fw_bus_type;
device->device.type = &fw_device_type;
- device->device.parent = device->card->device;
+ device->device.parent = card->device;
device->device.devt = MKDEV(fw_cdev_major, minor);
dev_set_name(&device->device, "fw%d", minor);

@@ -1016,7 +1019,7 @@ static void fw_device_init(struct work_s
&device->attribute_group);

if (device_add(&device->device)) {
- fw_error("Failed to add device.\n");
+ fw_err(card, "failed to add device\n");
goto error_with_cdev;
}

@@ -1037,18 +1040,10 @@ static void fw_device_init(struct work_s
PREPARE_DELAYED_WORK(&device->work, fw_device_shutdown);
fw_schedule_device_work(device, SHUTDOWN_DELAY);
} else {
- if (device->config_rom_retries)
- fw_notify("created device %s: GUID %08x%08x, S%d00, "
- "%d config ROM retries\n",
- dev_name(&device->device),
- device->config_rom[3], device->config_rom[4],
- 1 << device->max_speed,
- device->config_rom_retries);
- else
- fw_notify("created device %s: GUID %08x%08x, S%d00\n",
- dev_name(&device->device),
- device->config_rom[3], device->config_rom[4],
- 1 << device->max_speed);
+ fw_notice(card, "created device %s: GUID %08x%08x, S%d00\n",
+ dev_name(&device->device),
+ device->config_rom[3], device->config_rom[4],
+ 1 << device->max_speed);
device->config_rom_retries = 0;

set_broadcast_channel(device, device->generation);
@@ -1060,8 +1055,8 @@ static void fw_device_init(struct work_s
* just end up running the IRM work a couple of extra times -
* pretty harmless.
*/
- if (device->node == device->card->root_node)
- fw_schedule_bm_work(device->card, 0);
+ if (device->node == card->root_node)
+ fw_schedule_bm_work(card, 0);

return;

@@ -1165,12 +1160,13 @@ static void fw_device_refresh(struct wor
FW_DEVICE_RUNNING) == FW_DEVICE_GONE)
goto gone;

- fw_notify("refreshed device %s\n", dev_name(&device->device));
+ fw_notice(card, "refreshed device %s\n", dev_name(&device->device));
device->config_rom_retries = 0;
goto out;

give_up:
- fw_notify("giving up on refresh of device %s\n", dev_name(&device->device));
+ fw_notice(card, "giving up on refresh of device %s\n",
+ dev_name(&device->device));
gone:
atomic_set(&device->state, FW_DEVICE_GONE);
PREPARE_DELAYED_WORK(&device->work, fw_device_shutdown);
--- a/drivers/firewire/core-topology.c
+++ b/drivers/firewire/core-topology.c
@@ -205,19 +205,19 @@ static struct fw_node *build_tree(struct
next_sid = count_ports(sid, &port_count, &child_port_count);

if (next_sid == NULL) {
- fw_error("Inconsistent extended self IDs.\n");
+ fw_err(card, "inconsistent extended self IDs\n");
return NULL;
}

q = *sid;
if (phy_id != SELF_ID_PHY_ID(q)) {
- fw_error("PHY ID mismatch in self ID: %d != %d.\n",
- phy_id, SELF_ID_PHY_ID(q));
+ fw_err(card, "PHY ID mismatch in self ID: %d != %d\n",
+ phy_id, SELF_ID_PHY_ID(q));
return NULL;
}

if (child_port_count > stack_depth) {
- fw_error("Topology stack underflow\n");
+ fw_err(card, "topology stack underflow\n");
return NULL;
}

@@ -235,7 +235,7 @@ static struct fw_node *build_tree(struct

node = fw_node_create(q, port_count, card->color);
if (node == NULL) {
- fw_error("Out of memory while building topology.\n");
+ fw_err(card, "out of memory while building topology\n");
return NULL;
}

@@ -284,8 +284,8 @@ static struct fw_node *build_tree(struct
*/
if ((next_sid == end && parent_count != 0) ||
(next_sid < end && parent_count != 1)) {
- fw_error("Parent port inconsistency for node %d: "
- "parent_count=%d\n", phy_id, parent_count);
+ fw_err(card, "parent port inconsistency for node %d: "
+ "parent_count=%d\n", phy_id, parent_count);
return NULL;
}

@@ -530,7 +530,7 @@ void fw_core_handle_bus_reset(struct fw_
*/
if (!is_next_generation(generation, card->generation) &&
card->local_node != NULL) {
- fw_notify("skipped bus generations, destroying all nodes\n");
+ fw_notice(card, "skipped bus generations, destroying all nodes\n");
fw_destroy_nodes(card);
card->bm_retries = 0;
}
@@ -557,7 +557,7 @@ void fw_core_handle_bus_reset(struct fw_
card->color++;

if (local_node == NULL) {
- fw_error("topology build failed\n");
+ fw_err(card, "topology build failed\n");
/* FIXME: We need to issue a bus reset in this case. */
} else if (card->local_node == NULL) {
card->local_node = local_node;
--- a/drivers/firewire/core-transaction.c
+++ b/drivers/firewire/core-transaction.c
@@ -770,7 +770,7 @@ static struct fw_request *allocate_reque
break;

default:
- fw_error("ERROR - corrupt request received - %08x %08x %08x\n",
+ fw_notice(card, "ERROR - corrupt request received - %08x %08x %08x\n",
p->header[0], p->header[1], p->header[2]);
return NULL;
}
@@ -950,7 +950,7 @@ void fw_core_handle_response(struct fw_c

if (&t->link == &card->transaction_list) {
timed_out:
- fw_notify("Unsolicited response (source %x, tlabel %x)\n",
+ fw_notice(card, "unsolicited response (source %x, tlabel %x)\n",
source, tlabel);
return;
}
--- a/drivers/firewire/core.h
+++ b/drivers/firewire/core.h
@@ -1,6 +1,7 @@
#ifndef _FIREWIRE_CORE_H
#define _FIREWIRE_CORE_H

+#include <linux/compiler.h>
#include <linux/device.h>
#include <linux/fs.h>
#include <linux/list.h>
@@ -24,6 +25,11 @@ struct fw_packet;

/* -card */

+extern __printf(2, 3)
+void fw_err(const struct fw_card *card, const char *fmt, ...);
+extern __printf(2, 3)
+void fw_notice(const struct fw_card *card, const char *fmt, ...);
+
/* bitfields within the PHY registers */
#define PHY_LINK_ACTIVE 0x80
#define PHY_CONTENDER 0x40
--- a/include/linux/firewire.h
+++ b/include/linux/firewire.h
@@ -17,9 +17,6 @@
#include <linux/atomic.h>
#include <asm/byteorder.h>

-#define fw_notify(s, args...) printk(KERN_NOTICE KBUILD_MODNAME ": " s, ## args)
-#define fw_error(s, args...) printk(KERN_ERR KBUILD_MODNAME ": " s, ## args)
-
#define CSR_REGISTER_BASE 0xfffff0000000ULL

/* register offsets are relative to CSR_REGISTER_BASE */


--
Stefan Richter
-=====-===-- --=- =--=-
http://arcgraph.de/sr/

2012-02-18 21:32:24

by Joe Perches

[permalink] [raw]
Subject: Re: [PATCH 3/4] firewire: net: prefix all log messages with interface name

On Sat, 2012-02-18 at 22:02 +0100, Stefan Richter wrote:
> Change the log line prefix from "firewire_net: " to
> "firewire_net firewire0: " etc. for the case that several RFC 2734
> interfaces are being used in the same machine.

Why not just "firewireX: " ?

[]
> +#define fwnet_notice(net, fmt, args...) \
> + printk(KERN_NOTICE "%s %s: " fmt, KBUILD_MODNAME, (net)->name, ## args)
> +#define fwnet_err(net, fmt, args...) \
> + printk(KERN_ERR "%s %s: " fmt, KBUILD_MODNAME, (net)->name, ## args)

Adding code for the "%s:...", KBUILD_MODNAME rarely saves
overall space. Did you try embedding KBUILD_MODNAME
without the "%s: " and comparing the size?

Perhaps just add pr_fmt and pr_<level>?

#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt /* (if really necessary) */

and

#define fwnet_notice(net, fmt, ...) \
pr_notice("%s: " fmt, (net)->name, ##__VA_ARGS__)
#define fwnet_err(net, fmt, ...) \
pr_err("%s: " fmt, (net)->name, ##__VA_ARGS__)

2012-02-19 11:48:53

by Stefan Richter

[permalink] [raw]
Subject: Re: [PATCH 3/4] firewire: net: prefix all log messages with interface name

On Feb 18 Joe Perches wrote:
> On Sat, 2012-02-18 at 22:02 +0100, Stefan Richter wrote:
> > Change the log line prefix from "firewire_net: " to
> > "firewire_net firewire0: " etc. for the case that several RFC 2734
> > interfaces are being used in the same machine.
>
> Why not just "firewireX: " ?

The double prefix is strangely verbose and pedantic, but it does make
immediately obvious which driver emitted the message (as opposed to one of
the lower-level firewire drivers, or one of the upper-level networking
drivers).

For somebody who is familiar with the drivers --- or after full text search
through the source --- the firewire_net part is of course superfluous.

> []
> > +#define fwnet_notice(net, fmt, args...) \
> > + printk(KERN_NOTICE "%s %s: " fmt, KBUILD_MODNAME, (net)->name, ## args)
> > +#define fwnet_err(net, fmt, args...) \
> > + printk(KERN_ERR "%s %s: " fmt, KBUILD_MODNAME, (net)->name, ## args)
>
> Adding code for the "%s:...", KBUILD_MODNAME rarely saves
> overall space. Did you try embedding KBUILD_MODNAME
> without the "%s: " and comparing the size?
>
> Perhaps just add pr_fmt and pr_<level>?
>
> #define pr_fmt(fmt) KBUILD_MODNAME ": " fmt /* (if really necessary) */
>
> and
>
> #define fwnet_notice(net, fmt, ...) \
> pr_notice("%s: " fmt, (net)->name, ##__VA_ARGS__)
> #define fwnet_err(net, fmt, ...) \
> pr_err("%s: " fmt, (net)->name, ##__VA_ARGS__)

I think I tried it when I wrote the patch, hence the "module size is a
little bit decreased because KBUILD_MODNAME is now moved from the format
strings into a %s argument" in the changelog. But I wrote this quite a
while ago, so I better try again.

This is on linux-3.2 elf64-x86-64 with a few debug options, gcc-4.5.3.
Before yesterday's patch:
$ size firewire-net.ko; du -b firewire-net.ko
text data bss dec hex filename
9499 744 24 10267 281b firewire-net.ko
209777 firewire-net.ko

With the patch that I posted yesterday:
text data bss dec hex filename
9613 744 24 10381 288d firewire-net.ko
210056 firewire-net.ko

Weird, I must have done something differently back then. Wrongly, for
example.

With module name in the format strings:
#define fwnet_notice(net, fmt, args...) \
printk(KERN_NOTICE KBUILD_MODNAME " %s: " fmt, (net)->name, ## args)
#define fwnet_err(net, fmt, args...) \
printk(KERN_ERR KBUILD_MODNAME " %s: " fmt, (net)->name, ## args)

text data bss dec hex filename
9613 744 24 10381 288d firewire-net.ko
209760 firewire-net.ko

Without the module name, i.e.:
#define fwnet_notice(net, fmt, args...) \
printk(KERN_NOTICE "%s: " fmt, (net)->name, ## args)
#define fwnet_err(net, fmt, args...) \
printk(KERN_ERR "%s: " fmt, (net)->name, ## args)

text data bss dec hex filename
9483 744 24 10251 280b firewire-net.ko
209632 firewire-net.ko

So how about the following patch, for sake of countering kernel bloat?
text data bss dec hex filename
9430 744 24 10198 27d6 firewire-net.ko
209659 firewire-net.ko

--------------------------------- 8< ---------------------------------

Subject: [PATCH 3/4] firewire: net: use dev_printk API

Change the log line prefix from "firewire_net: " to "net firewire0: "
etc. for the case that several RFC 2734 interfaces are being used in the
same machine.

Note, the netdev_printk API is not very useful to firewire-net.
netdev_notice(net, "abc\n") would result in irritating messages like
"firewire_ohci 0000:0a:00.0: firewire0: abc". Nor would a dev_printk on
the fw_unit.device to which firewire-net is being bound be useful,
because there are generally multiple ones of those per interface (from
all RFC 2734 peers on the bus, the local node being only one of them).

In the initialization message of each interface, log the PCI device
name of the card which is parent of the netdevice instead of the GUID
of the peer which was semi-randomly used to establish the netdevice.

Signed-off-by: Stefan Richter <[email protected]>
---
drivers/firewire/net.c | 41 +++++++++++++++++++++--------------------
1 file changed, 21 insertions(+), 20 deletions(-)

--- a/drivers/firewire/net.c
+++ b/drivers/firewire/net.c
@@ -256,8 +256,8 @@ static int fwnet_header_rebuild(struct s
if (get_unaligned_be16(&h->h_proto) == ETH_P_IP)
return arp_find((unsigned char *)&h->h_dest, skb);

- fw_notify("%s: unable to resolve type %04x addresses\n",
- skb->dev->name, be16_to_cpu(h->h_proto));
+ dev_notice(&skb->dev->dev, "unable to resolve type %04x addresses\n",
+ be16_to_cpu(h->h_proto));
return 0;
}

@@ -369,7 +369,7 @@ static struct fwnet_fragment_info *fwnet

new = kmalloc(sizeof(*new), GFP_ATOMIC);
if (!new) {
- fw_error("out of memory\n");
+ dev_err(&pd->skb->dev->dev, "out of memory\n");
return NULL;
}

@@ -414,7 +414,7 @@ fail_w_fi:
fail_w_new:
kfree(new);
fail:
- fw_error("out of memory\n");
+ dev_err(&net->dev, "out of memory\n");

return NULL;
}
@@ -554,7 +554,7 @@ static int fwnet_finish_incoming_packet(
sspd = arp1394->sspd;
/* Sanity check. OS X 10.3 PPC reportedly sends 131. */
if (sspd > SCODE_3200) {
- fw_notify("sspd %x out of range\n", sspd);
+ dev_notice(&net->dev, "sspd %x out of range\n", sspd);
sspd = SCODE_3200;
}
max_payload = fwnet_max_payload(arp1394->max_rec, sspd);
@@ -574,8 +574,9 @@ static int fwnet_finish_incoming_packet(
spin_unlock_irqrestore(&dev->lock, flags);

if (!peer) {
- fw_notify("No peer for ARP packet from %016llx\n",
- (unsigned long long)peer_guid);
+ dev_notice(&net->dev,
+ "no peer for ARP packet from %016llx\n",
+ (unsigned long long)peer_guid);
goto no_peer;
}

@@ -691,7 +692,7 @@ static int fwnet_incoming_packet(struct

skb = dev_alloc_skb(len + net->hard_header_len + 15);
if (unlikely(!skb)) {
- fw_error("out of memory\n");
+ dev_err(&net->dev, "out of memory\n");
net->stats.rx_dropped++;

return -ENOMEM;
@@ -814,7 +815,7 @@ static void fwnet_receive_packet(struct
rcode = RCODE_TYPE_ERROR;
else if (fwnet_incoming_packet(dev, payload, length,
source, generation, false) != 0) {
- fw_error("Incoming packet failure\n");
+ dev_err(&dev->netdev->dev, "incoming packet failure\n");
rcode = RCODE_CONFLICT_ERROR;
} else
rcode = RCODE_COMPLETE;
@@ -881,7 +882,7 @@ static void fwnet_receive_broadcast(stru
if (retval >= 0)
fw_iso_context_queue_flush(dev->broadcast_rcv_context);
else
- fw_error("requeue failed\n");
+ dev_err(&dev->netdev->dev, "requeue failed\n");
}

static struct kmem_cache *fwnet_packet_task_cache;
@@ -936,9 +937,10 @@ static void fwnet_transmit_packet_done(s
case RFC2374_HDR_LASTFRAG:
case RFC2374_HDR_UNFRAG:
default:
- fw_error("Outstanding packet %x lf %x, header %x,%x\n",
- ptask->outstanding_pkts, lf, ptask->hdr.w0,
- ptask->hdr.w1);
+ dev_err(&dev->netdev->dev,
+ "outstanding packet %x lf %x, header %x,%x\n",
+ ptask->outstanding_pkts, lf, ptask->hdr.w0,
+ ptask->hdr.w1);
BUG();

case RFC2374_HDR_FIRSTFRAG:
@@ -1010,8 +1012,9 @@ static void fwnet_write_complete(struct
fwnet_transmit_packet_failed(ptask);

if (printk_timed_ratelimit(&j, 1000) || rcode != last_rcode) {
- fw_error("fwnet_write_complete: "
- "failed: %x (skipped %d)\n", rcode, errors_skipped);
+ dev_err(&ptask->dev->netdev->dev,
+ "fwnet_write_complete failed: %x (skipped %d)\n",
+ rcode, errors_skipped);

errors_skipped = 0;
last_rcode = rcode;
@@ -1539,14 +1542,12 @@ static int fwnet_probe(struct device *_d
put_unaligned_be64(card->guid, net->dev_addr);
put_unaligned_be64(~0ULL, net->broadcast);
ret = register_netdev(net);
- if (ret) {
- fw_error("Cannot register the driver\n");
+ if (ret)
goto out;
- }

list_add_tail(&dev->dev_link, &fwnet_device_list);
- fw_notify("%s: IPv4 over FireWire on device %016llx\n",
- net->name, (unsigned long long)card->guid);
+ dev_notice(&net->dev, "IPv4 over IEEE 1394 on card %s\n",
+ dev_name(card->device));
have_dev:
ret = fwnet_add_peer(dev, unit, device);
if (ret && allocated_netdev) {


--
Stefan Richter
-=====-===-- --=- =--==
http://arcgraph.de/sr/