Files
linux-nvgpu/drivers/gpu/nvgpu/os/linux/log.c
Alex Waterman 6b1302f23c gpu: nvgpu: Reduce linux debug log spew
Currently when nvgpu prints debug information for something like an MMU
fault the result includes a lot of usless boiler plate logging spew. In
some cases this can be helpful in identifying where the log message came
from in the nvgpu code base. However, for debug spews from faults, the
viewer of that info does not care which function printed the log (for
example).

Instead having a fast and readable debug dump is more valuable. So to
that end, add a special debug dump printing function that does not use
the normal log format. Instead, it prints only a breif prefix to use as
a grep search query. The new print out is listed below.

Since often the kernel logs are impressively long and obtuse, having a
clear debug search string can be helpful. With this log format, one can
simply do:

  $ grep __$CHIP__ kernel.log

And find any debug logs for the desired chip.

New log format - collected on a gv11b under L4T running
`nvgpu_submit_mmu_fault':

[   32.005793] nvgpu: 17000000.gv11b      gv11b_fb_mmu_fault_info_dump:311  [ERR]  [MMU FAULT] mmu engine id:  32, ch id:  511, fault addr: 0x1000, fault addr aperture: 0, fault type: invalid pde, access type: virt read,
[   32.006137] nvgpu: 17000000.gv11b      gv11b_fb_mmu_fault_info_dump:320  [ERR]  [MMU FAULT] protected mode: 0, client type: hub, client id:  host, gpc id if client type is gpc: 0,
[   32.006417] nvgpu: 17000000.gv11b                nvgpu_rc_mmu_fault:296  [ERR]  mmu fault id=0 id_type=1 act_eng_bitmask=00000000
[   32.007125] __gv11b__ Channel Status - chip gv11b
[   32.007128] __gv11b__ ---------------------------
[   32.007241] __gv11b__ 511-gv11b, TSG: 0, pid 955, refs: 2, deterministic:
[   32.007364] __gv11b__ channel status:  in use pending busy
[   32.007509] __gv11b__ RAMFC : TOP: 8000000000001000 PUT: 0000000000001030 GET: 0000000000001000 FETCH: 0000600000001000HEADER: 60400000 COUNT: 00000000SEMAPHORE: addr 0000000000000000payload 0000000000000000 execute 00000000
[   32.007601] __gv11b__
[   32.008696] __gv11b__
[   32.008700] __gv11b__ PBDMA Status - chip gv11b
[   32.008894] __gv11b__ -------------------------
[   32.013477] __gv11b__ pbdma 0:
[   32.017840] __gv11b__   id: -1 - [channel] next_id: - -1 [channel] | status: invalid
[   32.020992] __gv11b__   PBDMA_PUT 0000000000001030 PBDMA_GET 0000000000001000
[   32.029037] __gv11b__   GP_PUT    00000001  GP_GET  00000001  FETCH   00000001 HEADER 60400000
[   32.036386] __gv11b__   HDR       00000000  SHADOW0 00001000  SHADOW1 80003000
[   32.044787] __gv11b__ pbdma 1:
[   32.051964] __gv11b__   id: -1 - [channel] next_id: - -1 [channel] | status: invalid
[   32.055099] __gv11b__   PBDMA_PUT 0000000042003200 PBDMA_GET 00000050728bc914
[   32.062997] __gv11b__   GP_PUT    00000000  GP_GET  2080a000  FETCH   00000000 HEADER e1850010
[   32.070424] __gv11b__   HDR       00110000  SHADOW0 02000000  SHADOW1 10000004
[   32.078652] __gv11b__ pbdma 2:
[   32.085913] __gv11b__   id: -1 - [channel] next_id: - -1 [channel] | status: invalid
[   32.088973] __gv11b__   PBDMA_PUT 00000021040c0004 PBDMA_GET 0000000140020000
[   32.096502] __gv11b__   GP_PUT    00000000  GP_GET  8080a440  FETCH   00000000 HEADER 61400040
[   32.103679] __gv11b__   HDR       14000010  SHADOW0 00000000  SHADOW1 00000400
[   32.112336] __gv11b__
[   32.119860] __gv11b__ gv11b eng 0:
[   32.122119] __gv11b__ id: -1 (channel), next_id: -1 (channel), ctx status: invalid
[   32.125807] __gv11b__
[   32.135954] __gv11b__ gv11b eng 1:
[   32.135958] __gv11b__ id: -1 (channel), next_id: -1 (channel), ctx status: invalid
[   32.139457] __gv11b__
[   32.149945] __gv11b__ gv11b eng 2:
[   32.149950] __gv11b__ id: -1 (channel), next_id: -1 (channel), ctx status: invalid
[   32.153543] __gv11b__
[   32.163598] __gv11b__ gv11b eng 3:
[   32.163601] __gv11b__ id: -1 (channel), next_id: -1 (channel), ctx status: invalid
[   32.167278] __gv11b__
[   32.177076] __gv11b__
[   32.186145] nvgpu: 17000000.gv11b       nvgpu_tsg_set_ctx_mmu_error:492  [ERR]  TSG 0 generated a mmu fault
[   32.189443] nvgpu: 17000000.gv11b     nvgpu_set_err_notifier_locked:140  [ERR]  error notifier set to 31 for ch 511

JIRA NVGPU-5541

Change-Id: Iad60adfab5198ee11dd2ec595f2422ea541b7a2a
Signed-off-by: Alex Waterman <alexw@nvidia.com>
Reviewed-on: https://git-master.nvidia.com/r/c/linux-nvgpu/+/2349166
Tested-by: mobile promotions <svcmobile_promotions@nvidia.com>
Reviewed-by: mobile promotions <svcmobile_promotions@nvidia.com>
2020-12-15 14:13:28 -06:00

135 lines
3.6 KiB
C

/*
* Copyright (c) 2017-2019, NVIDIA CORPORATION. All rights reserved.
*
* This program is free software; you can redistribute it and/or modify it
* under the terms and conditions of the GNU General Public License,
* version 2, as published by the Free Software Foundation.
*
* This program is distributed in the hope it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
* more details.
*
* You should have received a copy of the GNU General Public License
* along with this program. If not, see <http://www.gnu.org/licenses/>.
*/
#include <linux/kernel.h>
#include <linux/device.h>
#include <nvgpu/linux/log.h>
#include <nvgpu/gk20a.h>
#include "platform_gk20a.h"
#include "os_linux.h"
/*
* Define a length for log buffers. This is the buffer that the 'fmt, ...' part
* of __nvgpu_do_log_print() prints into. This buffer lives on the stack so it
* needs to not be overly sized since we have limited kernel stack space. But at
* the same time we don't want it to be restrictive either.
*/
#define LOG_BUFFER_LENGTH 160
/*
* Annoying quirk of Linux: this has to be a string literal since the printk()
* function and friends use the preprocessor to concatenate stuff to the start
* of this string when printing.
*/
#define LOG_FMT "nvgpu: %s %33s:%-4d [%s] %s\n"
static const char *log_types[] = {
"ERR",
"WRN",
"DBG",
"INFO",
};
static inline const char *nvgpu_log_name(struct gk20a *g)
{
return dev_name(dev_from_gk20a(g));
}
#ifdef CONFIG_GK20A_TRACE_PRINTK
static void __nvgpu_trace_printk_log(u32 trace, const char *gpu_name,
const char *func_name, int line,
const char *log_type, const char *log)
{
trace_printk(LOG_FMT, gpu_name, func_name, line, log_type, log);
}
#endif
static void __nvgpu_really_print_log(u32 trace, const char *gpu_name,
const char *func_name, int line,
enum nvgpu_log_type type, const char *log)
{
const char *name = gpu_name ? gpu_name : "";
const char *log_type = log_types[type];
#ifdef CONFIG_GK20A_TRACE_PRINTK
if (trace)
return __nvgpu_trace_printk_log(trace, name, func_name,
line, log_type, log);
#endif
switch (type) {
case NVGPU_DEBUG:
/*
* We could use pr_debug() here but we control debug enablement
* separately from the Linux kernel. Perhaps this is a bug in
* nvgpu.
*/
pr_info(LOG_FMT, name, func_name, line, log_type, log);
break;
case NVGPU_INFO:
pr_info(LOG_FMT, name, func_name, line, log_type, log);
break;
case NVGPU_WARNING:
pr_warn(LOG_FMT, name, func_name, line, log_type, log);
break;
case NVGPU_ERROR:
pr_err(LOG_FMT, name, func_name, line, log_type, log);
break;
default:
break;
}
}
__attribute__((format (printf, 5, 6)))
void nvgpu_log_msg_impl(struct gk20a *g, const char *func_name, int line,
enum nvgpu_log_type type, const char *fmt, ...)
{
char log[LOG_BUFFER_LENGTH];
va_list args;
va_start(args, fmt);
(void) vsnprintf(log, LOG_BUFFER_LENGTH, fmt, args);
va_end(args);
__nvgpu_really_print_log(0, g ? nvgpu_log_name(g) : "",
func_name, line, type, log);
}
__attribute__((format (printf, 5, 6)))
void nvgpu_log_dbg_impl(struct gk20a *g, u64 log_mask,
const char *func_name, int line,
const char *fmt, ...)
{
char log[LOG_BUFFER_LENGTH];
va_list args;
if ((log_mask & g->log_mask) == 0)
return;
va_start(args, fmt);
(void) vsnprintf(log, LOG_BUFFER_LENGTH, fmt, args);
va_end(args);
__nvgpu_really_print_log(g->log_trace, nvgpu_log_name(g),
func_name, line, NVGPU_DEBUG, log);
}
void nvgpu_dbg_dump_impl(struct gk20a *g, const char *str)
{
pr_err("__%s__ %s", g->name, str);
}