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

在 2020年11月20日 13:56, HAGIO KAZUHITO(萩尾　一仁) 写道: > 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 > Thanks for the patch, Kazu and John. This patch looks good. Acked-by: Lianbo Jiang <lijiang(a)redhat.com&gt;

> 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"); > >