[Crash-utility] [RFC PATCH 1/1] crash: printk: add support for lockless ringbuffer

Linux is moving to 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; --- Makefile | 5 + defs.h | 24 +++++ kernel.c | 8 +- printk.c | 298 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 334 insertions(+), 1 deletion(-) create mode 100644 printk.c diff --git a/Makefile b/Makefile index 7455410..cec8ede 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 d8eda5e..253fabb 100644 --- a/defs.h +++ b/defs.h @@ -1906,12 +1906,30 @@ struct offset_table { /* stash of commonly-used offsets */ long rt_prio_array_queue; long task_struct_rt; long sched_rt_entity_run_list; + long log_seq; long log_ts_nsec; long log_len; long log_text_len; long log_dict_len; long log_level; long log_flags_level; + long log_caller_id; + long prb_desc_ring; + long prb_text_data_ring; + long prb_dict_data_ring; + long prb_fail; + long prb_desc_ring_count_bits; + long prb_desc_ring_descs; + long prb_desc_ring_head_id; + long prb_desc_ring_tail_id; + long prb_desc_info; + long prb_desc_state_var; + long prb_desc_text_blk_lpos; + long prb_desc_dict_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 timekeeper_xtime_sec; long neigh_table_hash_mask; long sched_rt_entity_my_q; @@ -1983,6 +2001,7 @@ struct offset_table { /* stash of commonly-used offsets */ long kmem_cache_cpu_cache; long nsproxy_net_ns; long atomic_t_counter; + long atomic_long_t_counter; long percpu_counter_count; long mm_struct_mm_count; long task_struct_thread_reg29; @@ -2222,6 +2241,11 @@ struct size_table { /* stash of commonly-used sizes */ long msg_queue; long log; long log_level; + long printk_ringbuffer; + long prb_desc_ring; + long prb_desc; + long prb_data_blk_lpos; + long prb_data_ring; long rt_rq; long task_group; long vmap_area; diff --git a/kernel.c b/kernel.c index 7604fac..a9889ea 100644 --- a/kernel.c +++ b/kernel.c @@ -95,6 +95,7 @@ static ulong __dump_audit(char *); static void dump_audit(void); static char *vmcoreinfo_read_string(const char *); static void check_vmcoreinfo(void); +void dump_lockless_record_log(int); /* @@ -4956,6 +4957,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); @@ -5196,7 +5202,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 0000000..e8aff4f --- /dev/null +++ b/printk.c @@ -0,0 +1,298 @@ +#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 *text_data_ring; + unsigned long text_data_ring_size; + char *text_data; + + char *dict_data_ring; + unsigned long dict_data_ring_size; + char *dict_data; +}; + +static void +init_offsets(void) +{ + char *n; + + n = "printk_info"; + STRUCT_SIZE_INIT(log, n); + MEMBER_OFFSET_INIT(log_seq, n, "seq"); + MEMBER_OFFSET_INIT(log_ts_nsec, n, "ts_nsec"); + MEMBER_OFFSET_INIT(log_len, n, "len"); + MEMBER_OFFSET_INIT(log_text_len, n, "text_len"); + MEMBER_OFFSET_INIT(log_dict_len, n, "dict_len"); + MEMBER_OFFSET_INIT(log_level, n, "level"); + MEMBER_SIZE_INIT(log_level, n, "level"); + MEMBER_OFFSET_INIT(log_flags_level, n, "flags_level"); + MEMBER_OFFSET_INIT(log_caller_id, n, "caller_id"); + + 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"); + MEMBER_OFFSET_INIT(prb_dict_data_ring, n, "dict_data_ring"); + MEMBER_OFFSET_INIT(prb_fail, n, "fail"); + + n = "prb_desc_ring"; + STRUCT_SIZE_INIT(prb_desc_ring, n); + 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_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_info, n, "info"); + MEMBER_OFFSET_INIT(prb_desc_state_var, n, "state_var"); + MEMBER_OFFSET_INIT(prb_desc_text_blk_lpos, n, "text_blk_lpos"); + MEMBER_OFFSET_INIT(prb_desc_dict_blk_lpos, n, "dict_blk_lpos"); + + n = "prb_data_blk_lpos"; + STRUCT_SIZE_INIT(prb_data_blk_lpos, n); + MEMBER_OFFSET_INIT(prb_data_blk_lpos_begin, n, "begin"); + MEMBER_OFFSET_INIT(prb_data_blk_lpos_next, n, "next"); + + n = "prb_data_ring"; + STRUCT_SIZE_INIT(prb_data_ring, n); + 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 short dict_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; + uint64_t seq; + int ilen = 0; + char *info; + char *text; + int indent; + char *desc; + ulong rem; + char *p; + int i; + + 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 = desc + OFFSET(prb_desc_info); + + /* available, but not shown :-( */ + seq = ULONGLONG(info + OFFSET(log_seq)); + caller_id = UINT(info + OFFSET(log_caller_id)); + + text_len = USHORT(info + OFFSET(log_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(log_ts_nsec)); + nanos = (ulonglong)ts_nsec / (ulonglong)1000000000; + rem = (ulonglong)ts_nsec % (ulonglong)1000000000; + sprintf(buf, "[%5lld.%06ld] ", nanos, rem/1000); + ilen += strlen(buf); + fprintf(fp, "%s", buf); + } + + if (msg_flags & SHOW_LOG_LEVEL) { + level = UCHAR(info + OFFSET(log_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); + } + + dict_len = USHORT(info + OFFSET(log_dict_len)); + + if (dict_len & (msg_flags & SHOW_LOG_DICT)) { + begin = ULONG(desc + OFFSET(prb_desc_dict_blk_lpos) + + OFFSET(prb_data_blk_lpos_begin)) % + m->dict_data_ring_size; + next = ULONG(desc + OFFSET(prb_desc_dict_blk_lpos) + + OFFSET(prb_data_blk_lpos_next)) % + m->dict_data_ring_size; + + /* ignore data-less dict blocks */ + if (begin == next) + goto out; + + /* handle wrapping data block */ + if (begin > next) + begin = 0; + + /* skip over descriptor ID */ + begin += sizeof(unsigned long); + + /* handle truncated messages */ + if (next - begin < dict_len) + dict_len = next - begin; + + text = m->dict_data + begin; + + fprintf(fp, "\n"); + indent = TRUE; + + for (i = 0, p = text; i < dict_len; i++, p++) { + if (indent) { + fprintf(fp, "%s", space(ilen)); + indent = FALSE; + } + if (isprint(*p)) + fputc(*p, fp); + else if (*p == NULLCHAR) { + fputc('\n', fp); + indent = TRUE; + } else + fputc('.', fp); + } + } +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(log)) + 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; + } + + /* 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; + } + + /* setup dict data ring */ + m.dict_data_ring = m.prb + OFFSET(prb_dict_data_ring); + m.dict_data_ring_size = 1 << UINT(m.dict_data_ring + + OFFSET(prb_data_ring_size_bits)); + kaddr = ULONG(m.dict_data_ring + OFFSET(prb_data_ring_data)); + m.dict_data = GETBUF(m.dict_data_ring_size); + if (!readmem(kaddr, KVADDR, m.dict_data, m.dict_data_ring_size, + "prb_dict_data_ring contents", RETURN_ON_ERROR|QUIET)) { + error(WARNING, "\ncannot read prb_dict_data_ring contents\n"); + goto out_dict_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); + + hq_close(); + +out_dict_data: + FREEBUF(m.dict_data); +out_text_data: + FREEBUF(m.text_data); +out_descs: + FREEBUF(m.descs); +out_prb: + FREEBUF(m.prb); +} -- 2.20.1