7 files changed, 146 insertions, 38 deletions

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 @@ __attribute__((weak)) int eioctl(int fd, unsigned long cmd, void *data = nullptr
         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 @@ __attribute__((weak)) int eopen(const char *pathname, int flags) {
         throw Exception("Failed to open device");
     }
 
+    Log(Severity::Debug) << "open. fd=" << fd << ", path='" << pathname << "', flags=" << flags << endl;
+
     return fd;
 }
 
@@ -63,6 +126,8 @@ eppoll(struct pollfd *fds, nfds_t nfds, const struct timespec *tmo_p, const sigs
 }
 
 __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 @@ __attribute((weak)) void *emmap(void *addr, size_t length, int prot, int flags,
         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 @@ ostream &operator<<(ostream &out, const SemanticVersion &v) {
  ****************************************************************************/
 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 @@ Buffer::Buffer(const Device &device, const size_t capacity) : fd(-1), dataPtr(nu
         } 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 @@ Buffer::~Buffer() noexcept(false) {
         } 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 @@ Network::Network(const Device &device, shared_ptr<Buffer> &buffer) : fd(-1), buf
         } 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 @@ Network::Network(const Device &device, const unsigned index) : fd(-1) {
         } 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 @@ void Network::collectNetworkInfo() {
 
 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 @@ ostream &operator<<(ostream &out, const InferenceStatus &status) {
 
 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 @@ void Inference::create(std::vector<uint32_t> &counterConfigs, bool cycleCounterE
     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 @@ static void ethosu_buffer_destroy(struct kref *kref)
 	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 @@ static int ethosu_buffer_release(struct inode *inode,
 {
 	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 @@ static int ethosu_buffer_mmap(struct file *file,
 	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 @@ static long ethosu_buffer_ioctl(struct file *file,
 	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 @@ static long ethosu_buffer_ioctl(struct file *file,
 			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 @@ static long ethosu_buffer_ioctl(struct file *file,
 		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 @@ int ethosu_buffer_create(struct ethosu_device *edev,
 	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 @@ int ethosu_cancel_inference_request(struct ethosu_inference *inf,
 		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 @@ deregister:
 
 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 @@ static int ethosu_open(struct inode *inode,
 
 	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 @@ static long ethosu_ioctl(struct file *file,
 	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 @@ static long ethosu_ioctl(struct file *file,
 		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 @@ static long ethosu_ioctl(struct file *file,
 		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 @@ static long ethosu_inference_ioctl(struct file *file,
 	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 @@ static long ethosu_inference_ioctl(struct file *file,
 		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 @@ static long ethosu_inference_ioctl(struct file *file,
 	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 @@ int ethosu_inference_create(struct ethosu_device *edev,
 	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 @@ static void ethosu_network_destroy(struct kref *kref)
 	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 @@ static int ethosu_network_release(struct inode *inode,
 {
 	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 @@ static long ethosu_network_ioctl(struct file *file,
 	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 @@ static long ethosu_network_ioctl(struct file *file,
 			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 @@ static long ethosu_network_ioctl(struct file *file,
 			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 @@ int ethosu_network_create(struct ethosu_device *edev,
 	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 @@ int ethosu_network_info_request(struct ethosu_network *net,
 	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 @@ int ethosu_network_info_request(struct ethosu_network *net,
 	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 @@ deregister:
 	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 @@ void ethosu_network_info_rsp(struct ethosu_device *edev,
 	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;