Improved logging
Add logging class for driver library. Log severity can be configured
using an environment variable.
Add information to prints in kernel space.
Change-Id: I19a1078869733746726515a6cafb79110314066d
diff --git a/driver_library/src/ethosu.cpp b/driver_library/src/ethosu.cpp
index eeb95c2..662fed7 100644
--- a/driver_library/src/ethosu.cpp
+++ b/driver_library/src/ethosu.cpp
@@ -20,8 +20,10 @@
#include <uapi/ethosu.h>
#include <algorithm>
+#include <cstdlib>
#include <exception>
#include <fstream>
+#include <iomanip>
#include <iostream>
#include <fcntl.h>
@@ -33,6 +35,62 @@
using namespace std;
+namespace {
+
+enum class Severity { Error, Warning, Info, Debug };
+
+class Log {
+public:
+ Log(const Severity _severity = Severity::Error) : severity(_severity) {}
+
+ ~Log() = default;
+
+ template <typename T>
+ const Log &operator<<(const T &d) const {
+ if (level >= severity) {
+ cout << d;
+ }
+
+ return *this;
+ }
+
+ const Log &operator<<(ostream &(*manip)(ostream &)) const {
+ if (level >= severity) {
+ manip(cout);
+ }
+
+ return *this;
+ }
+
+private:
+ static Severity getLogLevel() {
+ if (const char *e = getenv("ETHOSU_LOG_LEVEL")) {
+ const string env(e);
+
+ if (env == "Error") {
+ return Severity::Error;
+ } else if (env == "Warning") {
+ return Severity::Warning;
+ } else if (env == "Info") {
+ return Severity::Info;
+ } else if (env == "Debug") {
+ return Severity::Debug;
+ } else {
+ cerr << "Unsupported log level '" << env << "'" << endl;
+ }
+ }
+
+ return Severity::Warning;
+ }
+
+ static const Severity level;
+ const Severity severity;
+};
+
+const Severity Log::level = Log::getLogLevel();
+
+} // namespace
+
namespace EthosU {
__attribute__((weak)) int eioctl(int fd, unsigned long cmd, void *data = nullptr) {
int ret = ::ioctl(fd, cmd, data);
@@ -40,6 +98,9 @@
throw EthosU::Exception("IOCTL failed");
}
+ Log(Severity::Debug) << "ioctl. fd=" << fd << ", cmd=" << setw(8) << setfill('0') << hex << cmd << ", ret=" << ret
+ << endl;
+
return ret;
}
@@ -49,6 +110,8 @@
throw Exception("Failed to open device");
}
+ Log(Severity::Debug) << "open. fd=" << fd << ", path='" << pathname << "', flags=" << flags << endl;
+
return fd;
}
@@ -63,6 +126,8 @@
}
__attribute__((weak)) int eclose(int fd) {
+ Log(Severity::Debug) << "close. fd=" << fd << endl;
+
int result = ::close(fd);
if (result < 0) {
throw Exception("Failed to close file");
@@ -76,10 +141,15 @@
throw Exception("Failed to mmap file");
}
+ Log(Severity::Debug) << "map. fd=" << fd << ", addr=" << setfill('0') << addr << ", length=" << dec << length
+ << ", ptr=" << hex << ptr << endl;
+
return ptr;
}
__attribute__((weak)) int emunmap(void *addr, size_t length) {
+ Log(Severity::Debug) << "unmap. addr=" << setfill('0') << addr << ", length=" << dec << length << endl;
+
int result = ::munmap(addr, length);
if (result < 0) {
throw Exception("Failed to munmap file");
@@ -146,10 +216,12 @@
****************************************************************************/
Device::Device(const char *device) {
fd = eopen(device, O_RDWR | O_NONBLOCK);
+ Log(Severity::Info) << "Device(\"" << device << "\"). this=" << this << ", fd=" << fd << endl;
}
Device::~Device() noexcept(false) {
eclose(fd);
+ Log(Severity::Info) << "~Device(). this=" << this << endl;
}
int Device::ioctl(unsigned long cmd, void *data) const {
@@ -187,7 +259,11 @@
} catch (...) { std::throw_with_nested(e); }
throw;
}
+
dataPtr = reinterpret_cast<char *>(d);
+
+ Log(Severity::Info) << "Buffer(" << &device << ", " << dec << capacity << "), this=" << this << ", fd=" << fd
+ << ", dataPtr=" << static_cast<void *>(dataPtr) << endl;
}
Buffer::~Buffer() noexcept(false) {
@@ -199,7 +275,10 @@
} catch (...) { std::throw_with_nested(e); }
throw;
}
+
eclose(fd);
+
+ Log(Severity::Info) << "~Buffer(). this=" << this << endl;
}
size_t Buffer::capacity() const {
@@ -255,6 +334,8 @@
} catch (...) { std::throw_with_nested(e); }
throw;
}
+
+ Log(Severity::Info) << "Network(" << &device << ", " << &*buffer << "), this=" << this << ", fd=" << fd << endl;
}
Network::Network(const Device &device, const unsigned index) : fd(-1) {
@@ -271,6 +352,8 @@
} catch (...) { std::throw_with_nested(e); }
throw;
}
+
+ Log(Severity::Info) << "Network(" << &device << ", " << index << "), this=" << this << ", fd=" << fd << endl;
}
void Network::collectNetworkInfo() {
@@ -288,6 +371,7 @@
Network::~Network() noexcept(false) {
eclose(fd);
+ Log(Severity::Info) << "~Network(). this=" << this << endl;
}
int Network::ioctl(unsigned long cmd, void *data) {
@@ -350,6 +434,7 @@
Inference::~Inference() noexcept(false) {
eclose(fd);
+ Log(Severity::Info) << "~Inference(). this=" << this << endl;
}
void Inference::create(std::vector<uint32_t> &counterConfigs, bool cycleCounterEnable = false) {
@@ -384,6 +469,8 @@
uapi.pmu_config.cycle_count = cycleCounterEnable;
fd = network->ioctl(ETHOSU_IOCTL_INFERENCE_CREATE, static_cast<void *>(&uapi));
+
+ Log(Severity::Info) << "Inference(" << &*network << "), this=" << this << ", fd=" << fd << endl;
}
std::vector<uint32_t> Inference::initializeCounterConfig() {
diff --git a/kernel/ethosu_buffer.c b/kernel/ethosu_buffer.c
index 4f70f1d..ac32aca 100644
--- a/kernel/ethosu_buffer.c
+++ b/kernel/ethosu_buffer.c
@@ -126,10 +126,11 @@
struct ethosu_buffer *buf =
container_of(kref, struct ethosu_buffer, kref);
- dev_info(buf->edev->dev, "Buffer destroy. handle=0x%pK\n", buf);
+ dev_info(buf->edev->dev, "Buffer destroy. buf=0x%pK\n", buf);
dma_free_coherent(buf->edev->dev, buf->capacity, buf->cpu_addr,
buf->dma_addr_orig);
+
devm_kfree(buf->edev->dev, buf);
}
@@ -138,7 +139,8 @@
{
struct ethosu_buffer *buf = file->private_data;
- dev_info(buf->edev->dev, "Buffer release. handle=0x%pK\n", buf);
+ dev_info(buf->edev->dev, "Buffer release. file=0x%pK, buf=0x%pK\n",
+ file, buf);
ethosu_buffer_put(buf);
@@ -151,7 +153,8 @@
struct ethosu_buffer *buf = file->private_data;
int ret;
- dev_info(buf->edev->dev, "Buffer mmap. handle=0x%pK\n", buf);
+ dev_info(buf->edev->dev, "Buffer mmap. file=0x%pK, buf=0x%pK\n",
+ file, buf);
ret = dma_mmap_coherent(buf->edev->dev, vma, buf->cpu_addr,
buf->dma_addr_orig,
@@ -172,7 +175,9 @@
if (ret)
return ret;
- dev_info(buf->edev->dev, "Ioctl. cmd=%u, arg=%lu\n", cmd, arg);
+ dev_info(buf->edev->dev,
+ "Buffer ioctl. file=0x%pK, buf=0x%pK, cmd=0x%x, arg=%lu\n",
+ file, buf, cmd, arg);
switch (cmd) {
case ETHOSU_IOCTL_BUFFER_SET: {
@@ -182,7 +187,7 @@
break;
dev_info(buf->edev->dev,
- "Ioctl: Buffer set. size=%u, offset=%u\n",
+ "Buffer ioctl: Buffer set. size=%u, offset=%u\n",
uapi.size, uapi.offset);
ret = ethosu_buffer_resize(buf, uapi.size, uapi.offset);
@@ -195,7 +200,7 @@
uapi.offset = buf->offset;
dev_info(buf->edev->dev,
- "Ioctl: Buffer get. size=%u, offset=%u\n",
+ "Buffer ioctl: Buffer get. size=%u, offset=%u\n",
uapi.size, uapi.offset);
if (copy_to_user(udata, &uapi, sizeof(uapi)))
@@ -253,8 +258,8 @@
fput(buf->file);
dev_info(buf->edev->dev,
- "Buffer create. handle=0x%pK, capacity=%zu, cpu_addr=0x%pK, dma_addr=0x%llx, dma_addr_orig=0x%llx, phys_addr=0x%llx\n",
- buf, capacity, buf->cpu_addr, buf->dma_addr,
+ "Buffer create. file=0x%pK, fd=%d, buf=0x%pK, capacity=%zu, cpu_addr=0x%pK, dma_addr=0x%llx, dma_addr_orig=0x%llx, phys_addr=0x%llx\n",
+ buf->file, ret, buf, capacity, buf->cpu_addr, buf->dma_addr,
buf->dma_addr_orig, virt_to_phys(buf->cpu_addr));
return ret;
diff --git a/kernel/ethosu_cancel_inference.c b/kernel/ethosu_cancel_inference.c
index 6d93cf1..e2acb22 100644
--- a/kernel/ethosu_cancel_inference.c
+++ b/kernel/ethosu_cancel_inference.c
@@ -121,8 +121,8 @@
goto kfree;
dev_info(cancellation->edev->dev,
- "Inference cancellation create. Id=%d, handle=0x%p\n",
- cancellation->msg.id, cancellation);
+ "Inference cancellation create. cancel=0x%pK, msg.id=%d\n",
+ cancellation, cancellation->msg.id);
ret = ethosu_cancel_inference_send(cancellation);
if (0 != ret)
@@ -166,7 +166,7 @@
kfree:
dev_info(cancellation->edev->dev,
- "Cancel inference destroy. handle=0x%p\n", cancellation);
+ "Cancel inference destroy. cancel=0x%pK\n", cancellation);
/* decrease the reference on the inference we are refering to */
ethosu_inference_put(cancellation->inf);
devm_kfree(cancellation->edev->dev, cancellation);
diff --git a/kernel/ethosu_device.c b/kernel/ethosu_device.c
index 6bc3c28..0f1a284 100644
--- a/kernel/ethosu_device.c
+++ b/kernel/ethosu_device.c
@@ -291,7 +291,7 @@
file->private_data = edev;
- dev_info(edev->dev, "Opening device node.\n");
+ dev_info(edev->dev, "Device open. file=0x%pK\n", file);
return nonseekable_open(inode, file);
}
@@ -308,16 +308,20 @@
if (ret)
return ret;
- dev_info(edev->dev, "Ioctl. cmd=0x%x, arg=0x%lx\n", cmd, arg);
+ dev_info(edev->dev, "Device ioctl. file=0x%pK, cmd=0x%x, arg=0x%lx\n",
+ file, cmd, arg);
switch (cmd) {
case ETHOSU_IOCTL_VERSION_REQ:
- dev_info(edev->dev, "Ioctl: Send version request\n");
+ dev_info(edev->dev, "Device ioctl: Send version request\n");
ret = ethosu_mailbox_version_request(&edev->mailbox);
break;
case ETHOSU_IOCTL_CAPABILITIES_REQ: {
struct ethosu_uapi_device_capabilities uapi;
- dev_info(edev->dev, "Ioctl: Send capabilities request\n");
+
+ dev_info(edev->dev,
+ "Device ioctl: Send capabilities request\n");
+
ret = ethosu_capabilities_request(edev, &uapi);
if (ret)
break;
@@ -326,19 +330,18 @@
break;
}
case ETHOSU_IOCTL_PING: {
- dev_info(edev->dev, "Ioctl: Send ping\n");
+ dev_info(edev->dev, "Device ioctl: Send ping\n");
ret = ethosu_mailbox_ping(&edev->mailbox);
break;
}
case ETHOSU_IOCTL_BUFFER_CREATE: {
struct ethosu_uapi_buffer_create uapi;
- dev_info(edev->dev, "Ioctl: Buffer create\n");
-
if (copy_from_user(&uapi, udata, sizeof(uapi)))
break;
- dev_info(edev->dev, "Ioctl: Buffer. capacity=%u\n",
+ dev_info(edev->dev,
+ "Device ioctl: Buffer create. capacity=%u\n",
uapi.capacity);
ret = ethosu_buffer_create(edev, uapi.capacity);
@@ -350,7 +353,9 @@
if (copy_from_user(&uapi, udata, sizeof(uapi)))
break;
- dev_info(edev->dev, "Ioctl: Network. fd=%u\n", uapi.fd);
+ dev_info(edev->dev,
+ "Device ioctl: Network create. type=%u, fd/index=%u\n",
+ uapi.type, uapi.fd);
ret = ethosu_network_create(edev, &uapi);
break;
diff --git a/kernel/ethosu_inference.c b/kernel/ethosu_inference.c
index d2209fd..1a3c45a 100644
--- a/kernel/ethosu_inference.c
+++ b/kernel/ethosu_inference.c
@@ -237,7 +237,9 @@
if (ret)
return ret;
- dev_info(inf->edev->dev, "Ioctl: cmd=%u, arg=%lu", cmd, arg);
+ dev_info(inf->edev->dev,
+ "Inference ioctl: file=0x%pK, inf=0x%pK, cmd=0x%x, arg=%lu",
+ file, inf, cmd, arg);
switch (cmd) {
case ETHOSU_IOCTL_INFERENCE_STATUS: {
@@ -257,7 +259,7 @@
uapi.pmu_count.cycle_count = inf->pmu_cycle_counter_count;
dev_info(inf->edev->dev,
- "Ioctl: Inference status. status=%s (%d)\n",
+ "Inference ioctl: Inference status. status=%s (%d)\n",
status_to_string(uapi.status), uapi.status);
ret = copy_to_user(udata, &uapi, sizeof(uapi)) ? -EFAULT : 0;
@@ -267,7 +269,8 @@
case ETHOSU_IOCTL_INFERENCE_CANCEL: {
struct ethosu_uapi_cancel_inference_status uapi;
- dev_info(inf->edev->dev, "Ioctl: Cancel Inference. Handle=%p\n",
+ dev_info(inf->edev->dev,
+ "Inference ioctl: Cancel Inference. Handle=%p\n",
inf);
ret = ethosu_cancel_inference_request(inf, &uapi);
@@ -385,8 +388,9 @@
inf->file = fget(ret);
fput(inf->file);
- dev_info(edev->dev, "Inference create. Id=%d, handle=0x%p, fd=%d",
- inf->msg.id, inf, fd);
+ dev_info(edev->dev,
+ "Inference create. file=0x%pK, fd=%d, inf=0x%p, net=0x%pK, msg.id=0x%x",
+ inf->file, fd, inf, inf->net, inf->msg.id);
return fd;
diff --git a/kernel/ethosu_network.c b/kernel/ethosu_network.c
index 4170046..251b181 100644
--- a/kernel/ethosu_network.c
+++ b/kernel/ethosu_network.c
@@ -68,7 +68,7 @@
struct ethosu_network *net =
container_of(kref, struct ethosu_network, kref);
- dev_info(net->edev->dev, "Network destroy. handle=0x%pK\n", net);
+ dev_info(net->edev->dev, "Network destroy. net=0x%pK\n", net);
if (net->buf != NULL)
ethosu_buffer_put(net->buf);
@@ -81,7 +81,8 @@
{
struct ethosu_network *net = file->private_data;
- dev_info(net->edev->dev, "Network release. handle=0x%pK\n", net);
+ dev_info(net->edev->dev, "Network release. file=0x%pK, net=0x%pK\n",
+ file, net);
ethosu_network_put(net);
@@ -100,7 +101,9 @@
if (ret)
return ret;
- dev_info(net->edev->dev, "Ioctl: cmd=0x%x, arg=0x%lx\n", cmd, arg);
+ dev_info(net->edev->dev,
+ "Network ioctl: file=0x%pK, net=0x%pK, cmd=0x%x, arg=0x%lx\n",
+ file, net, cmd, arg);
switch (cmd) {
case ETHOSU_IOCTL_NETWORK_INFO: {
@@ -110,7 +113,7 @@
break;
dev_info(net->edev->dev,
- "Ioctl: Network info. handle=%p\n",
+ "Network ioctl: Network info. net=0x%pK\n",
net);
ret = ethosu_network_info_request(net, &uapi);
@@ -127,7 +130,7 @@
break;
dev_info(net->edev->dev,
- "Ioctl: Inference. ifm_fd=%u, ofm_fd=%u\n",
+ "Network ioctl: Inference. ifm_fd=%u, ofm_fd=%u\n",
uapi.ifm_fd[0], uapi.ofm_fd[0]);
ret = ethosu_inference_create(net->edev, net, &uapi);
@@ -177,8 +180,9 @@
net->file = fget(ret);
fput(net->file);
- dev_info(edev->dev, "Network create. handle=0x%pK",
- net);
+ dev_info(edev->dev,
+ "Network create. file=0x%pK, fd=%d, net=0x%pK, buf=0x%pK, index=%u",
+ net->file, ret, net, net->buf, net->index);
return ret;
diff --git a/kernel/ethosu_network_info.c b/kernel/ethosu_network_info.c
index 52adf9c..a99ca84 100644
--- a/kernel/ethosu_network_info.c
+++ b/kernel/ethosu_network_info.c
@@ -99,8 +99,9 @@
if (ret)
goto deregister;
- dev_info(info->edev->dev, "Network info create. Id=%d, handle=0x%p\n\n",
- info->msg.id, info);
+ dev_info(info->edev->dev,
+ "Network info create. info=0x%pK, net=0x%pK, msg.id=0x%x\n",
+ info, info->net, info->msg.id);
/* Unlock the device mutex and wait for completion */
mutex_unlock(&info->edev->mutex);
@@ -110,7 +111,8 @@
mutex_lock(&info->edev->mutex);
if (0 == timeout) {
- dev_warn(info->edev->dev, "Network info timed out.");
+ dev_warn(info->edev->dev, "Network info timed out. info=0x%pK",
+ info);
ret = -ETIME;
goto deregister;
@@ -123,8 +125,9 @@
ethosu_network_put(info->net);
kfree:
- dev_info(info->edev->dev, "Network info destroy. Id=%d, handle=0x%p\n",
- info->msg.id, info);
+ dev_info(info->edev->dev,
+ "Network info destroy. info=0x%pK, msg.id=0x%x\n",
+ info, info->msg.id);
devm_kfree(info->edev->dev, info);
return ret;
@@ -142,7 +145,7 @@
msg = ethosu_mailbox_find(&edev->mailbox, id);
if (IS_ERR(msg)) {
dev_warn(edev->dev,
- "Id for network info msg not found. Id=%d\n",
+ "Id for network info msg not found. msg.id=0x%x\n",
id);
return;