From 53fd03d0b8d02fa0be0aa9db4dce8766be459031 Mon Sep 17 00:00:00 2001 From: Kristofer Jonsson Date: Tue, 21 Jun 2022 16:58:45 +0200 Subject: 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 --- driver_library/src/ethosu.cpp | 87 ++++++++++++++++++++++++++++++++++++++++ kernel/ethosu_buffer.c | 21 ++++++---- kernel/ethosu_cancel_inference.c | 6 +-- kernel/ethosu_device.c | 23 ++++++----- kernel/ethosu_inference.c | 14 ++++--- kernel/ethosu_network.c | 18 +++++---- kernel/ethosu_network_info.c | 15 ++++--- 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 #include +#include #include #include +#include #include #include @@ -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 + 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(d); + + Log(Severity::Info) << "Buffer(" << &device << ", " << dec << capacity << "), this=" << this << ", fd=" << fd + << ", dataPtr=" << static_cast(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) : 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 &counterConfigs, bool cycleCounterEnable = false) { @@ -384,6 +469,8 @@ void Inference::create(std::vector &counterConfigs, bool cycleCounterE uapi.pmu_config.cycle_count = cycleCounterEnable; fd = network->ioctl(ETHOSU_IOCTL_INFERENCE_CREATE, static_cast(&uapi)); + + Log(Severity::Info) << "Inference(" << &*network << "), this=" << this << ", fd=" << fd << endl; } std::vector 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; -- cgit v1.2.1