Re: [Crash-utility] [PATCH] printk: add support for lockless ringbuffer

From: John Ogness <john.ogness(a)linutronix.de&gt; Linux 5.10 introduces a new lockless ringbuffer. The new ringbuffer is structured completely different to the previous iterations. Add support for dumping the ringbuffer with the "log" command. The new ringbuffer is detected based on the availability of the "prb" symbol. Signed-off-by: John Ogness <john.ogness(a)linutronix.de&gt; Signed-off-by: Kazuhito Hagio <k-hagio-ab(a)nec.com&gt; --- I've updated John's RFC crash patch to match 5.10-rc4 kernel. Changes from the RFC patch: - followed the following kernel commits cfe2790b163a ("printk: move printk_info into separate array") 74caba7f2a06 ("printk: move dictionary keys to dev_printk_info") f35efc78add6 ("printk: remove dict ring") - moved the added members in offset_table and size_table to the end of them - print offsets and sizes with "help -o" option - support "log -T" option

Makefile | 5 ++ defs.h | 30 ++++++++ kernel.c | 7 +- printk.c | 255 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ symbols.c | 27 +++++++ 5 files changed, 323 insertions(+), 1 deletion(-) create mode 100644 printk.c diff --git a/Makefile b/Makefile index d1857190c2fb..f66eba7418d1 100644 --- a/Makefile +++ b/Makefile @@ -61,6 +61,7 @@ VMWARE_HFILES=vmware_vmss.h CFILES=main.c tools.c global_data.c memory.c filesys.c help.c task.c \ kernel.c test.c gdb_interface.c configure.c net.c dev.c bpf.c \ + printk.c \ alpha.c x86.c ppc.c ia64.c s390.c s390x.c s390dbf.c ppc64.c x86_64.c \ arm.c arm64.c mips.c sparc64.c \ extensions.c remote.c va_server.c va_server_v1.c symbols.c cmdline.c \ @@ -80,6 +81,7 @@ SOURCE_FILES=${CFILES} ${GENERIC_HFILES} ${MCORE_HFILES} \ OBJECT_FILES=main.o tools.o global_data.o memory.o filesys.o help.o task.o \ build_data.o kernel.o test.o gdb_interface.o net.o dev.o bpf.o \ + printk.o \ alpha.o x86.o ppc.o ia64.o s390.o s390x.o s390dbf.o ppc64.o x86_64.o \ arm.o arm64.o mips.o sparc64.o \ extensions.o remote.o va_server.o va_server_v1.o symbols.o cmdline.o \ @@ -363,6 +365,9 @@ task.o: ${GENERIC_HFILES} task.c kernel.o: ${GENERIC_HFILES} kernel.c ${CC} -c ${CRASH_CFLAGS} kernel.c ${WARNING_OPTIONS} ${WARNING_ERROR} +printk.o: ${GENERIC_HFILES} printk.c + ${CC} -c ${CRASH_CFLAGS} printk.c ${WARNING_OPTIONS} ${WARNING_ERROR} + gdb_interface.o: ${GENERIC_HFILES} gdb_interface.c ${CC} -c ${CRASH_CFLAGS} gdb_interface.c ${WARNING_OPTIONS} ${WARNING_ERROR} diff --git a/defs.h b/defs.h index 95949507cae4..e1a18e9d0b4d 100644 --- a/defs.h +++ b/defs.h @@ -2106,6 +2106,28 @@ struct offset_table { /* stash of commonly-used offsets */ long irq_common_data_affinity; long irq_desc_irq_common_data; long uts_namespace_name; + long printk_info_seq; + long printk_info_ts_nsec; + long printk_info_text_len; + long printk_info_level; + long printk_info_caller_id; + long printk_info_dev_info; + long dev_printk_info_subsystem; + long dev_printk_info_device; + long prb_desc_ring; + long prb_text_data_ring; + long prb_desc_ring_count_bits; + long prb_desc_ring_descs; + long prb_desc_ring_infos; + long prb_desc_ring_head_id; + long prb_desc_ring_tail_id; + long prb_desc_state_var; + long prb_desc_text_blk_lpos; + long prb_data_blk_lpos_begin; + long prb_data_blk_lpos_next; + long prb_data_ring_size_bits; + long prb_data_ring_data; + long atomic_long_t_counter; }; struct size_table { /* stash of commonly-used sizes */ @@ -2265,6 +2287,9 @@ struct size_table { /* stash of commonly-used sizes */ long xa_node; long zram_table_entry; long irq_common_data; + long printk_info; + long printk_ringbuffer; + long prb_desc; }; struct array_table { @@ -6697,6 +6722,11 @@ int vmware_guestdump_memory_dump(FILE *); int calc_kaslr_offset(ulong *, ulong *); /* + * printk.c + */ +void dump_lockless_record_log(int); + +/* * gnu_binutils.c */ diff --git a/kernel.c b/kernel.c index 98716372c8be..e722ff941527 100644 --- a/kernel.c +++ b/kernel.c @@ -5042,6 +5042,11 @@ dump_log(int msg_flags) struct syment *nsp; int log_wrap, loglevel, log_buf_len; + if (kernel_symbol_exists("prb")) { + dump_lockless_record_log(msg_flags); + return; + } + if (kernel_symbol_exists("log_first_idx") && kernel_symbol_exists("log_next_idx")) { dump_variable_length_record_log(msg_flags); @@ -5289,7 +5294,7 @@ dump_log_entry(char *logptr, int msg_flags) } /* - * Handle the new variable-length-record log_buf. + * Handle the variable-length-record log_buf. */ static void dump_variable_length_record_log(int msg_flags) diff --git a/printk.c b/printk.c new file mode 100644 index 000000000000..7be721853cf9 --- /dev/null +++ b/printk.c @@ -0,0 +1,255 @@ +#include "defs.h" +#include <ctype.h> + +#define DESC_SV_BITS (sizeof(unsigned long) * 8) +#define DESC_COMMITTED_MASK (1UL << (DESC_SV_BITS - 1)) +#define DESC_REUSE_MASK (1UL << (DESC_SV_BITS - 2)) +#define DESC_FLAGS_MASK (DESC_COMMITTED_MASK | DESC_REUSE_MASK) +#define DESC_ID_MASK (~DESC_FLAGS_MASK) + +/* convenience struct for passing many values to helper functions */ +struct prb_map { + char *prb; + + char *desc_ring; + unsigned long desc_ring_count; + char *descs; + char *infos; + + char *text_data_ring; + unsigned long text_data_ring_size; + char *text_data; +}; + +static void +init_offsets(void) +{ + char *n; + + n = "printk_info"; + STRUCT_SIZE_INIT(printk_info, n); + MEMBER_OFFSET_INIT(printk_info_seq, n, "seq"); + MEMBER_OFFSET_INIT(printk_info_ts_nsec, n, "ts_nsec"); + MEMBER_OFFSET_INIT(printk_info_text_len, n, "text_len"); + MEMBER_OFFSET_INIT(printk_info_level, n, "level"); + MEMBER_OFFSET_INIT(printk_info_caller_id, n, "caller_id"); + MEMBER_OFFSET_INIT(printk_info_dev_info, n, "dev_info"); + + n = "dev_printk_info"; + MEMBER_OFFSET_INIT(dev_printk_info_subsystem, n, "subsystem"); + MEMBER_OFFSET_INIT(dev_printk_info_device, n, "device"); + + n = "printk_ringbuffer"; + STRUCT_SIZE_INIT(printk_ringbuffer, n); + MEMBER_OFFSET_INIT(prb_desc_ring, n, "desc_ring"); + MEMBER_OFFSET_INIT(prb_text_data_ring, n, "text_data_ring"); + + n = "prb_desc_ring"; + MEMBER_OFFSET_INIT(prb_desc_ring_count_bits, n, "count_bits"); + MEMBER_OFFSET_INIT(prb_desc_ring_descs, n, "descs"); + MEMBER_OFFSET_INIT(prb_desc_ring_infos, n, "infos"); + MEMBER_OFFSET_INIT(prb_desc_ring_head_id, n, "head_id"); + MEMBER_OFFSET_INIT(prb_desc_ring_tail_id, n, "tail_id"); + + n = "prb_desc"; + STRUCT_SIZE_INIT(prb_desc, n); + MEMBER_OFFSET_INIT(prb_desc_state_var, n, "state_var"); + MEMBER_OFFSET_INIT(prb_desc_text_blk_lpos, n, "text_blk_lpos"); + + n = "prb_data_blk_lpos"; + MEMBER_OFFSET_INIT(prb_data_blk_lpos_begin, n, "begin"); + MEMBER_OFFSET_INIT(prb_data_blk_lpos_next, n, "next"); + + n = "prb_data_ring"; + MEMBER_OFFSET_INIT(prb_data_ring_size_bits, n, "size_bits"); + MEMBER_OFFSET_INIT(prb_data_ring_data, n, "data"); + + n = "atomic_long_t"; + MEMBER_OFFSET_INIT(atomic_long_t_counter, n, "counter"); +} + +static void +dump_record(struct prb_map *m, unsigned long id, int msg_flags) +{ + unsigned short text_len; + unsigned long state_var; + unsigned int caller_id; + unsigned char level; + unsigned long begin; + unsigned long next; + char buf[BUFSIZE]; + uint64_t ts_nsec; + ulonglong nanos; + ulonglong seq; + int ilen = 0, i; + char *desc, *info, *text, *p; + ulong rem; + + desc = m->descs + ((id % m->desc_ring_count) * SIZE(prb_desc)); + + /* skip non-committed record */ + state_var = ULONG(desc + OFFSET(prb_desc_state_var) + + OFFSET(atomic_long_t_counter)); + if ((state_var & DESC_FLAGS_MASK) != DESC_COMMITTED_MASK) + return; + + info = m->infos + ((id % m->desc_ring_count) * SIZE(printk_info)); + + seq = ULONGLONG(info + OFFSET(printk_info_seq)); + caller_id = UINT(info + OFFSET(printk_info_caller_id)); + if (CRASHDEBUG(1)) + fprintf(fp, "seq: %llu caller_id: %u\n", seq, caller_id); + + text_len = USHORT(info + OFFSET(printk_info_text_len)); + + begin = ULONG(desc + OFFSET(prb_desc_text_blk_lpos) + + OFFSET(prb_data_blk_lpos_begin)) % + m->text_data_ring_size; + next = ULONG(desc + OFFSET(prb_desc_text_blk_lpos) + + OFFSET(prb_data_blk_lpos_next)) % + m->text_data_ring_size; + + /* skip data-less text blocks */ + if (begin == next) + goto out; + + if ((msg_flags & SHOW_LOG_TEXT) == 0) { + ts_nsec = ULONGLONG(info + OFFSET(printk_info_ts_nsec)); + nanos = (ulonglong)ts_nsec / (ulonglong)1000000000; + rem = (ulonglong)ts_nsec % (ulonglong)1000000000; + if (msg_flags & SHOW_LOG_CTIME) { + time_t t = kt->boot_date.tv_sec + nanos; + sprintf(buf, "[%s] ", ctime_tz(&t)); + } else + sprintf(buf, "[%5lld.%06ld] ", nanos, rem/1000); + + ilen += strlen(buf); + fprintf(fp, "%s", buf); + } + + if (msg_flags & SHOW_LOG_LEVEL) { + level = UCHAR(info + OFFSET(printk_info_level)) >> 5; + sprintf(buf, "<%x>", level); + ilen += strlen(buf); + fprintf(fp, "%s", buf); + } + + /* handle wrapping data block */ + if (begin > next) + begin = 0; + + /* skip over descriptor ID */ + begin += sizeof(unsigned long); + + /* handle truncated messages */ + if (next - begin < text_len) + text_len = next - begin; + + text = m->text_data + begin; + + for (i = 0, p = text; i < text_len; i++, p++) { + if (*p == '\n') + fprintf(fp, "\n%s", space(ilen)); + else if (isprint(*p) || isspace(*p)) + fputc(*p, fp); + else + fputc('.', fp); + } + + if (msg_flags & SHOW_LOG_DICT) { + text = info + OFFSET(printk_info_dev_info) + + OFFSET(dev_printk_info_subsystem); + if (strlen(text)) + fprintf(fp, "\n%sSUBSYSTEM=%s", space(ilen), text); + + text = info + OFFSET(printk_info_dev_info) + + OFFSET(dev_printk_info_device); + if (strlen(text)) + fprintf(fp, "\n%sDEVICE=%s", space(ilen), text); + } +out: + fprintf(fp, "\n"); +} + +/* + * Handle the lockless printk_ringbuffer. + */ +void +dump_lockless_record_log(int msg_flags) +{ + unsigned long head_id; + unsigned long tail_id; + unsigned long kaddr; + unsigned long id; + struct prb_map m; + + if (INVALID_SIZE(printk_info)) + init_offsets(); + + /* setup printk_ringbuffer */ + get_symbol_data("prb", sizeof(char *), &kaddr); + m.prb = GETBUF(SIZE(printk_ringbuffer)); + if (!readmem(kaddr, KVADDR, m.prb, SIZE(printk_ringbuffer), + "printk_ringbuffer contents", RETURN_ON_ERROR|QUIET)) { + error(WARNING, "\ncannot read printk_ringbuffer contents\n"); + goto out_prb; + } + + /* setup descriptor ring */ + m.desc_ring = m.prb + OFFSET(prb_desc_ring); + m.desc_ring_count = 1 << UINT(m.desc_ring + OFFSET(prb_desc_ring_count_bits)); + + kaddr = ULONG(m.desc_ring + OFFSET(prb_desc_ring_descs)); + m.descs = GETBUF(SIZE(prb_desc) * m.desc_ring_count); + if (!readmem(kaddr, KVADDR, m.descs, SIZE(prb_desc) * m.desc_ring_count, + "prb_desc_ring contents", RETURN_ON_ERROR|QUIET)) { + error(WARNING, "\ncannot read prb_desc_ring contents\n"); + goto out_descs; + } + + kaddr = ULONG(m.desc_ring + OFFSET(prb_desc_ring_infos)); + m.infos = GETBUF(SIZE(printk_info) * m.desc_ring_count); + if (!readmem(kaddr, KVADDR, m.infos, SIZE(printk_info) * m.desc_ring_count, + "prb_info_ring contents", RETURN_ON_ERROR|QUIET)) { + error(WARNING, "\ncannot read prb_info_ring contents\n"); + goto out_infos; + } + + /* setup text data ring */ + m.text_data_ring = m.prb + OFFSET(prb_text_data_ring); + m.text_data_ring_size = 1 << UINT(m.text_data_ring + OFFSET(prb_data_ring_size_bits)); + + kaddr = ULONG(m.text_data_ring + OFFSET(prb_data_ring_data)); + m.text_data = GETBUF(m.text_data_ring_size); + if (!readmem(kaddr, KVADDR, m.text_data, m.text_data_ring_size, + "prb_text_data_ring contents", RETURN_ON_ERROR|QUIET)) { + error(WARNING, "\ncannot read prb_text_data_ring contents\n"); + goto out_text_data; + } + + /* ready to go */ + + tail_id = ULONG(m.desc_ring + OFFSET(prb_desc_ring_tail_id) + + OFFSET(atomic_long_t_counter)); + head_id = ULONG(m.desc_ring + OFFSET(prb_desc_ring_head_id) + + OFFSET(atomic_long_t_counter)); + + hq_open(); + + for (id = tail_id; id != head_id; id = (id + 1) & DESC_ID_MASK) + dump_record(&m, id, msg_flags); + + /* dump head record */ + dump_record(&m, id, msg_flags); + + hq_close(); + +out_text_data: + FREEBUF(m.text_data); +out_infos: + FREEBUF(m.infos); +out_descs: + FREEBUF(m.descs); +out_prb: + FREEBUF(m.prb); +} diff --git a/symbols.c b/symbols.c index b2f4eb5402d1..a51078d58e6b 100644 --- a/symbols.c +++ b/symbols.c @@ -10426,6 +10426,30 @@ dump_offset_table(char *spec, ulong makestruct) OFFSET(log_level)); fprintf(fp, " log_flags_level: %ld\n", OFFSET(log_flags_level)); + + fprintf(fp, " printk_info_seq: %ld\n", OFFSET(printk_info_seq)); + fprintf(fp, " printk_info_ts_nseq: %ld\n", OFFSET(printk_info_ts_nsec)); + fprintf(fp, " printk_info_text_len: %ld\n", OFFSET(printk_info_text_len)); + fprintf(fp, " printk_info_level: %ld\n", OFFSET(printk_info_level)); + fprintf(fp, " printk_info_caller_id: %ld\n", OFFSET(printk_info_caller_id)); + fprintf(fp, " printk_info_dev_info: %ld\n", OFFSET(printk_info_dev_info)); + fprintf(fp, " dev_printk_info_subsystem: %ld\n", OFFSET(dev_printk_info_subsystem)); + fprintf(fp, " dev_printk_info_device: %ld\n", OFFSET(dev_printk_info_device)); + fprintf(fp, " prb_desc_ring: %ld\n", OFFSET(prb_desc_ring)); + fprintf(fp, " prb_text_data_ring: %ld\n", OFFSET(prb_text_data_ring)); + fprintf(fp, " prb_desc_ring_count_bits: %ld\n", OFFSET(prb_desc_ring_count_bits)); + fprintf(fp, " prb_desc_ring_descs: %ld\n", OFFSET(prb_desc_ring_descs)); + fprintf(fp, " prb_desc_ring_infos: %ld\n", OFFSET(prb_desc_ring_infos)); + fprintf(fp, " prb_desc_ring_head_id: %ld\n", OFFSET(prb_desc_ring_head_id)); + fprintf(fp, " prb_desc_ring_tail_id: %ld\n", OFFSET(prb_desc_ring_tail_id)); + fprintf(fp, " prb_desc_state_var: %ld\n", OFFSET(prb_desc_state_var)); + fprintf(fp, " prb_desc_text_blk_lpos: %ld\n", OFFSET(prb_desc_text_blk_lpos)); + fprintf(fp, " prb_data_blk_lpos_begin: %ld\n", OFFSET(prb_data_blk_lpos_begin)); + fprintf(fp, " prb_data_blk_lpos_next: %ld\n", OFFSET(prb_data_blk_lpos_next)); + fprintf(fp, " prb_data_ring_size_bits: %ld\n", OFFSET(prb_data_ring_size_bits)); + fprintf(fp, " prb_data_ring_data: %ld\n", OFFSET(prb_data_ring_data)); + fprintf(fp, " atomit_long_t_counter: %ld\n", OFFSET(atomic_long_t_counter)); + fprintf(fp, " sched_rt_entity_my_q: %ld\n", OFFSET(sched_rt_entity_my_q)); fprintf(fp, " task_group_parent: %ld\n", @@ -10850,6 +10874,9 @@ dump_offset_table(char *spec, ulong makestruct) SIZE(xarray)); fprintf(fp, " xa_node: %ld\n", SIZE(xa_node)); + fprintf(fp, " printk_info: %ld\n", SIZE(printk_info)); + fprintf(fp, " printk_ringbuffer: %ld\n", SIZE(printk_ringbuffer)); + fprintf(fp, " prb_desc: %ld\n", SIZE(prb_desc)); fprintf(fp, "\n array_table:\n");