From patchwork Thu Dec 12 20:32:35 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Patchwork-Submitter: Sean Paul X-Patchwork-Id: 11289397 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 6F14213B6 for ; Thu, 12 Dec 2019 20:33:09 +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 4A4FD2077B for ; Thu, 12 Dec 2019 20:33:09 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=fail reason="signature verification failed" (2048-bit key) header.d=poorly.run header.i=@poorly.run header.b="axuy9pMJ" DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 4A4FD2077B 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 E0C996E1C4; Thu, 12 Dec 2019 20:33:05 +0000 (UTC) X-Original-To: dri-devel@lists.freedesktop.org Delivered-To: dri-devel@lists.freedesktop.org Received: from mail-yb1-xb44.google.com (mail-yb1-xb44.google.com [IPv6:2607:f8b0:4864:20::b44]) by gabe.freedesktop.org (Postfix) with ESMTPS id 20B536E1C4 for ; Thu, 12 Dec 2019 20:33:04 +0000 (UTC) Received: by mail-yb1-xb44.google.com with SMTP id 63so1070981yba.2 for ; Thu, 12 Dec 2019 12:33:04 -0800 (PST) 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=eMrYedQRCiC47tt9PfqPg2AiayJD2saDTlabfUz4SIk=; b=axuy9pMJhPUOF5lZA5sRgD42q483OHb24pAYAjc4fy5pJF7iVpJIqvMfeb8L48Ksol tgtmbH5c6wL8yilpf9CfaJOBmxUGsRpQNIr7xc/FCLQuRltoT3OdPzwQGVqz4eSQwKDk 2SUZ8zvVSzKVR/A+5Td5ZYaVV9mFxkScrar6kKVxfA8CINeAstDrRAWRvg5a0oRfRsWE LLyFVqP3GcG+Ba/QCpRdLVg/Zg60fC0BYstJKmaYjyZJ8LJM5MqfdgtMA4tRc9yxJiz7 vlehuXhr9paTdgTzV1p51QSBRfQqVWMRMAamEzEnKy0UP5lhINXjvmLAlc0fAFA7gy9t IRFw== 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=eMrYedQRCiC47tt9PfqPg2AiayJD2saDTlabfUz4SIk=; b=ZIHp4sGMwN0czb+nFN3SWlEFYgK4am6fYeJvQ4QZdGMDrRctgRzj2p5lVwbu0fliuv JF7GgCtlcvGvNvjiIiaIifgtvO5AcKYRzZFQ2SiLNdvnvJF/rjmuiBKtLttGp1GC0DdJ xvUVfQeX5o8dxkwTgR3zYKbgBG/IQfe912VFmsdhb1c7YTEG32gYKLQAch7r305xWrr+ sTm16Z+1XaXLf6OdsncCm74snNJBPdbl4O1dGH8xUEFeqBXosRxg4E49RIi8RdUu5lzK TNRkRjw38eNikwC0diXlgOHroddAHFDI/FfJvZ5bQGCUTKlBDV8WHZTuBoJyzRrM22y1 9zqg== X-Gm-Message-State: APjAAAUglPFFHs14UzX4rWfO+6w7PCdDcA5jIMep17p9hrNEcvljG6GN nkTcWZ366FDk5cQ8F1MNpEneUtYGguPVWQ== X-Google-Smtp-Source: APXvYqxSWIISAsQBwSCFsYFFwP5Jtk2MKWcBIKVyshL3iIIS7Vn0orvYQH3Y0xmZDFgRJmmzsu1TGg== X-Received: by 2002:a25:3554:: with SMTP id c81mr2480319yba.164.1576182783006; Thu, 12 Dec 2019 12:33:03 -0800 (PST) Received: from localhost ([2620:0:1013:11:1e1:4760:6ce4:fc64]) by smtp.gmail.com with ESMTPSA id p133sm3099326ywb.71.2019.12.12.12.33.02 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 12 Dec 2019 12:33:02 -0800 (PST) From: Sean Paul To: dri-devel@lists.freedesktop.org Subject: [PATCH v3] drm: Funnel drm logs to tracepoints Date: Thu, 12 Dec 2019 15:32:35 -0500 Message-Id: <20191212203301.142437-1-sean@poorly.run> X-Mailer: git-send-email 2.24.1.735.g03f4e72817-goog MIME-Version: 1.0 X-BeenThere: dri-devel@lists.freedesktop.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Direct Rendering Infrastructure - Development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Sean Paul , David Airlie , Daniel Vetter , Ingo Molnar , Sean Paul , Steven Rostedt , Thomas Zimmermann Errors-To: dri-devel-bounces@lists.freedesktop.org Sender: "dri-devel" From: Sean Paul 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, users 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 to do. I spoke with airlied about this and RHEL has similar issues. After a few more people piped up on previous versions of this patch, it is a Real Issue. So why don't we just enable DRM_UT_BLAH? 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 So what we really want is a ringbuffer of the most recent logs (filtered by categories we're interested in) exposed via debugfs so the logs can be extracted when users file feedback. It just so happens that there is something which does _exactly_ this! This patch dumps drm logs into tracepoints, which allows us to turn tracing on and off depending on which category is useful, and pull them from tracefs on demand. What about trace_printk()? It doesn't give us the control we get from using tracepoints and it's not meant to be left sprinkled around in code. Cc: David Airlie Cc: Daniel Vetter Cc: Pekka Paalanen Cc: Joonas Lahtinen Cc: Thomas Zimmermann Cc: Rob Clark Cc: Ville Syrjälä Acked-by: Daniel Vetter Signed-off-by: Sean Paul Link: https://patchwork.freedesktop.org/patch/msgid/20191010204823.195540-1-sean@poorly.run #v1 Changes in v2: - Went with a completely different approach: https://lists.freedesktop.org/archives/dri-devel/2019-November/243230.html Changes in v3: - Changed commit message to be a bit less RFC-y - Make class_drm_category_log an actual trace class --- Even though we don't want it to be, this is UAPI. So here's some userspace code which uses it: https://chromium-review.googlesource.com/c/chromiumos/platform2/+/1965562 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..862728fe0f89 --- /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)) +); + +DECLARE_EVENT_CLASS(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