From patchwork Thu Oct 10 20:48:08 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Sean Paul X-Patchwork-Id: 11184403 Return-Path: Received: from mail.kernel.org (pdx-korg-mail-1.web.codeaurora.org [172.30.200.123]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 61DC114ED for ; Thu, 10 Oct 2019 20:48:29 +0000 (UTC) Received: from gabe.freedesktop.org (gabe.freedesktop.org [131.252.210.177]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id 48D29208C3 for ; Thu, 10 Oct 2019 20:48:28 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 48D29208C3 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=poorly.run Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=dri-devel-bounces@lists.freedesktop.org Received: from gabe.freedesktop.org (localhost [127.0.0.1]) by gabe.freedesktop.org (Postfix) with ESMTP id F076D89C84; Thu, 10 Oct 2019 20:48:26 +0000 (UTC) X-Original-To: dri-devel@lists.freedesktop.org Delivered-To: dri-devel@lists.freedesktop.org Received: from mail-yw1-xc43.google.com (mail-yw1-xc43.google.com [IPv6:2607:f8b0:4864:20::c43]) by gabe.freedesktop.org (Postfix) with ESMTPS id 9215289C84 for ; Thu, 10 Oct 2019 20:48:25 +0000 (UTC) Received: by mail-yw1-xc43.google.com with SMTP id r134so2689378ywg.2 for ; Thu, 10 Oct 2019 13:48:25 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:mime-version :content-transfer-encoding; bh=/SXMl77l1RCqLKMn9wGPfHmyqFcEU+G6lf8HDVyff/w=; b=a12NAT2EBBg4ObgdJJeE2Cy0GsVV9rw3wvE3QQ/ywLJwcbckPt3YadPFmoKvX+KHTB 2beQGFED0IvGGM+lK7UTYNceTvDQKKwHSgvIPtl4G17X5ww0anbP9ykoItCo9gAEO30L jUQZFHow6Nm4U6L1BL7RERM1Jtuy47x/B9daU6chxDaxpuLcyUuKOA2v2E9M9sriB9RD pTjZzVwtdJLrhr+xtV/Kta4L32pPUkWbbQYfLiUub0QszFG7VDdOIgmLN/yzUScEdJQ1 pUncHVUcA3V6vEaoIe/Pf/Lt909VjeQnIgJ+v0UWurX6ySxItu23UdqpCp+42dt0ilwf b3gg== X-Gm-Message-State: APjAAAX5MYcxr0Jz6+XPBXVMA/VJfRsCfdbyiNCWQDZ06yDQ46BRmVk+ P+79D6HaVC4eaZNAsDrtMMcrkZVYYgs= X-Google-Smtp-Source: APXvYqzi7ppgNZ/V9xEtgV/H4XTfE1y24OsmY9uEoSE3BabmrMpuI/YKAZWwBTirr3AqOnTnN2UDJQ== X-Received: by 2002:a81:1058:: with SMTP id 85mr8432506ywq.110.1570740504306; Thu, 10 Oct 2019 13:48:24 -0700 (PDT) Received: from rosewood.cam.corp.google.com ([2620:0:1013:11:89c6:2139:5435:371d]) by smtp.gmail.com with ESMTPSA id f10sm1767436ywf.21.2019.10.10.13.48.23 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 10 Oct 2019 13:48:23 -0700 (PDT) From: Sean Paul To: dri-devel@lists.freedesktop.org Subject: [PATCH] drm: Funnel drm logs to tracepoints Date: Thu, 10 Oct 2019 16:48:08 -0400 Message-Id: <20191010204823.195540-1-sean@poorly.run> X-Mailer: git-send-email 2.23.0.700.g56cf767bdb-goog MIME-Version: 1.0 X-Mailman-Original-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=poorly.run; s=google; h=from:to:cc:subject:date:message-id:mime-version :content-transfer-encoding; bh=/SXMl77l1RCqLKMn9wGPfHmyqFcEU+G6lf8HDVyff/w=; b=Qvcv9FcFQzFkaUe2PaWz0m2N2UTNzqRB+YDOWAGDU1sE2QV5Y8S6AIVRNbE2ll5a0G IUqnbT2QXrP63EYUORmcRkW01znl6ETc7vJ3hUUpDF0icCAy966yHOr9WafbOgpLN6rw rSWAi0JwTIheHeFC5XAqKl09SarDDJKYRJc0vYXLODs7Xjx4W/Tpmd2nz39eAiNAM2Ty kFpR5938x21BBtHVxxEZId6AT/iOwqWKDF9fH0AB9XNXXMWLl8dsdyVuQGeaeaXL42OK MhPnZtwhSCEhCWuuY1tzXMgorU/JURpFRkj5T1U9rcJHkDTh62UcpPjl1vtseo2nbyUQ OGhw== X-BeenThere: dri-devel@lists.freedesktop.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Direct Rendering Infrastructure - Development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: David Airlie , Sean Paul , Sean Paul , Daniel Vetter Errors-To: dri-devel-bounces@lists.freedesktop.org Sender: "dri-devel" From: Sean Paul *Record scratch* You read that subject correctly, I bet you're wondering how we got here. At least hear me out before you flame :-) For a long while now, we (ChromeOS) have been struggling getting any value out of user feedback reports of display failures (notably external displays not working). The problem is that all logging, even fatal errors (well, fatal in the sense that a display won't light up) are logged at DEBUG log level. So in order to extract these logs, you need to be able to turn on logging, and reproduce the issue with debug enabled. Unfortunately, this isn't really something we can ask CrOS users I spoke with airlied about this and RHEL has similar issues. This is the point where you ask me, "So Sean, why don't you just enable DRM_UT_BLAH?". Good question! Here are the reasons in ascending order of severity: 1- People aren't consistent with their categories, so we'd have to enable a bunch to get proper coverage 2- We don't want to overwhelm syslog with drm spam, others have to use it too 3- Console logging is slow Hopefully you're with me so far. I have a problem that has no existing solution. What I really want is a ringbuffer of the most recent logs (in the categories I'm interested in) exposed via debugfs so I can extract it when users file feedback. It just so happens that there is something which does _exactly_ this! I can dump the most recent logs into tracepoints, turn them on and off depending on which category I want, and pull them from debugfs on demand. "What about trace_printk()?" You'll say. It doesn't give us the control we get from using tracepoints and it's not meant to be left sprinkled around in code. So that is how we got here, now it's time for you to tell me why this is a horrible idea :-) Cc: David Airlie Cc: Daniel Vetter Signed-off-by: Sean Paul Acked-by: Daniel Vetter --- drivers/gpu/drm/drm_print.c | 143 ++++++++++++++++++++++++++----- include/trace/events/drm_print.h | 116 +++++++++++++++++++++++++ 2 files changed, 239 insertions(+), 20 deletions(-) create mode 100644 include/trace/events/drm_print.h diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c index 9a25d73c155c..f591292811aa 100644 --- a/drivers/gpu/drm/drm_print.c +++ b/drivers/gpu/drm/drm_print.c @@ -27,11 +27,15 @@ #include +#include #include #include #include #include +#define CREATE_TRACE_POINTS +#include + #include #include #include @@ -241,10 +245,10 @@ void drm_dev_printk(const struct device *dev, const char *level, struct va_format vaf; va_list args; - va_start(args, format); vaf.fmt = format; vaf.va = &args; + va_start(args, format); if (dev) dev_printk(level, dev, "[" DRM_NAME ":%ps] %pV", __builtin_return_address(0), &vaf); @@ -253,49 +257,145 @@ void drm_dev_printk(const struct device *dev, const char *level, level, __builtin_return_address(0), &vaf); va_end(args); + + va_start(args, format); + trace_drm_log(level, dev, &vaf); + va_end(args); } EXPORT_SYMBOL(drm_dev_printk); +static unsigned int drm_trace_enabled(unsigned int category) +{ + unsigned int bit; + + for_each_set_bit(bit, (unsigned long*)&category, sizeof(category) * 8) { + switch (BIT(bit)) { + case DRM_UT_NONE: + return trace_drm_dbg_none_enabled(); + case DRM_UT_CORE: + return trace_drm_dbg_core_enabled(); + case DRM_UT_DRIVER: + return trace_drm_dbg_driver_enabled(); + case DRM_UT_KMS: + return trace_drm_dbg_kms_enabled(); + case DRM_UT_PRIME: + return trace_drm_dbg_prime_enabled(); + case DRM_UT_ATOMIC: + return trace_drm_dbg_atomic_enabled(); + case DRM_UT_VBL: + return trace_drm_dbg_vbl_enabled(); + case DRM_UT_STATE: + return trace_drm_dbg_state_enabled(); + case DRM_UT_LEASE: + return trace_drm_dbg_lease_enabled(); + case DRM_UT_DP: + return trace_drm_dbg_dp_enabled(); + default: + return trace_drm_dbg_unknown_enabled(); + } + } + return false; +} + +static void drm_do_trace(const struct device *dev, unsigned int category, + struct va_format *vaf) +{ + WARN_ON(hweight32(category) > 1); + + switch (category) { + case DRM_UT_NONE: + trace_drm_dbg_none(dev, vaf); + break; + case DRM_UT_CORE: + trace_drm_dbg_core(dev, vaf); + break; + case DRM_UT_DRIVER: + trace_drm_dbg_driver(dev, vaf); + break; + case DRM_UT_KMS: + trace_drm_dbg_kms(dev, vaf); + break; + case DRM_UT_PRIME: + trace_drm_dbg_prime(dev, vaf); + break; + case DRM_UT_ATOMIC: + trace_drm_dbg_atomic(dev, vaf); + break; + case DRM_UT_VBL: + trace_drm_dbg_vbl(dev, vaf); + break; + case DRM_UT_STATE: + trace_drm_dbg_state(dev, vaf); + break; + case DRM_UT_LEASE: + trace_drm_dbg_lease(dev, vaf); + break; + case DRM_UT_DP: + trace_drm_dbg_dp(dev, vaf); + break; + default: + trace_drm_dbg_unknown(dev, vaf); + break; + } +} + void drm_dev_dbg(const struct device *dev, unsigned int category, const char *format, ...) { struct va_format vaf; + unsigned int bit; va_list args; - if (!drm_debug_enabled(category)) - return; - - va_start(args, format); vaf.fmt = format; vaf.va = &args; - if (dev) - dev_printk(KERN_DEBUG, dev, "[" DRM_NAME ":%ps] %pV", - __builtin_return_address(0), &vaf); - else - printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV", - __builtin_return_address(0), &vaf); + if (drm_debug_enabled(category)) { + va_start(args, format); + if (dev) + dev_printk(KERN_DEBUG, dev, "[" DRM_NAME ":%ps] %pV", + __builtin_return_address(0), &vaf); + else + printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV", + __builtin_return_address(0), &vaf); + va_end(args); + } + + if (!drm_trace_enabled(category)) + return; + + for_each_set_bit(bit, (unsigned long*)&category, sizeof(category) * 8) { + va_start(args, format); + drm_do_trace(dev, BIT(bit), &vaf); + va_end(args); + } - va_end(args); } EXPORT_SYMBOL(drm_dev_dbg); void drm_dbg(unsigned int category, const char *format, ...) { struct va_format vaf; + unsigned int bit; va_list args; - if (!drm_debug_enabled(category)) - return; - - va_start(args, format); vaf.fmt = format; vaf.va = &args; - printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV", - __builtin_return_address(0), &vaf); + if (drm_debug_enabled(category)) { + va_start(args, format); + printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV", + __builtin_return_address(0), &vaf); + va_end(args); + } - va_end(args); + if (!drm_trace_enabled(category)) + return; + + for_each_set_bit(bit, (unsigned long*)&category, sizeof(category) * 8) { + va_start(args, format); + drm_do_trace(NULL, BIT(bit), &vaf); + va_end(args); + } } EXPORT_SYMBOL(drm_dbg); @@ -304,13 +404,16 @@ void drm_err(const char *format, ...) struct va_format vaf; va_list args; - va_start(args, format); vaf.fmt = format; vaf.va = &args; + va_start(args, format); printk(KERN_ERR "[" DRM_NAME ":%ps] *ERROR* %pV", __builtin_return_address(0), &vaf); + va_end(args); + va_start(args, format); + trace_drm_err(NULL, &vaf); va_end(args); } EXPORT_SYMBOL(drm_err); diff --git a/include/trace/events/drm_print.h b/include/trace/events/drm_print.h new file mode 100644 index 000000000000..cc93c69f3fe4 --- /dev/null +++ b/include/trace/events/drm_print.h @@ -0,0 +1,116 @@ +// SPDX-License-Identifier: MIT +/* + * Copyright (C) 2019 Google, Inc. + * + * Authors: + * Sean Paul + */ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM drm_print + +#if !defined(_TRACE_DRM_PRINT_H) || defined(TRACE_HEADER_MULTI_READ) + +#include +#include + +#define DRM_PRINT_MAX 256 + +#define _TRACE_DRM_PRINT_H + +TRACE_EVENT(drm_log, + TP_PROTO(const char * level, const struct device *dev, + struct va_format *vaf), + TP_ARGS(level, dev, vaf), + TP_STRUCT__entry( + __field(const char *, level ) + __field(const struct device *, dev ) + __dynamic_array(char, msg, DRM_PRINT_MAX ) + __field(int, len ) + ), + TP_fast_assign( + __entry->level = level; + __entry->dev = dev; + __entry->len = vsnprintf(__get_str(msg), DRM_PRINT_MAX, + vaf->fmt, *vaf->va); + if (__entry->len > 0 && + __get_str(msg)[__entry->len - 1] == '\n') + __get_str(msg)[--__entry->len] = '\0'; + ), + TP_printk("%s %s %s: %s", __entry->level, + __entry->dev ? dev_driver_string(__entry->dev) : "(NULL):", + __entry->dev ? dev_name(__entry->dev) : "", __get_str(msg)) +); + +TRACE_EVENT(class_drm_category_log, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf), + TP_STRUCT__entry( + __field(const struct device *, dev ) + __dynamic_array(char, msg, DRM_PRINT_MAX ) + __field(int, len ) + ), + TP_fast_assign( + __entry->dev = dev; + __entry->len = vsnprintf(__get_str(msg), DRM_PRINT_MAX, + vaf->fmt, *vaf->va); + if (__entry->len > 0 && + __get_str(msg)[__entry->len - 1] == '\n') + __get_str(msg)[--__entry->len] = '\0'; + ), + TP_printk("%s %s%s%s", + __entry->dev ? dev_driver_string(__entry->dev) : "", + __entry->dev ? dev_name(__entry->dev) : "", + __entry->dev ? ": " : "", __get_str(msg)) +); +DEFINE_EVENT(class_drm_category_log, drm_err, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_none, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_core, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_driver, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_kms, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_prime, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_atomic, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_vbl, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_state, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_lease, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_dp, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +DEFINE_EVENT(class_drm_category_log, drm_dbg_unknown, + TP_PROTO(const struct device *dev, struct va_format *vaf), + TP_ARGS(dev, vaf) +); +#endif + +/* This part must be outside protection */ +#include