From 3e0d075cb0ab3b1fbddc14855985215407f8a48b Mon Sep 17 00:00:00 2001 From: John Ogness Date: Fri, 14 Aug 2020 23:31:24 +0206 Subject: scripts/gdb: add utils.read_ulong() Add a function for reading unsigned long values, which vary in size depending on the architecture. Signed-off-by: John Ogness Reviewed-by: Nick Desaulniers Tested-by: Nick Desaulniers Tested-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20200814212525.6118-2-john.ogness@linutronix.de --- scripts/gdb/linux/utils.py | 7 +++++++ 1 file changed, 7 insertions(+) (limited to 'scripts/gdb/linux') diff --git a/scripts/gdb/linux/utils.py b/scripts/gdb/linux/utils.py index ea94221dbd39..ff7c1799d588 100644 --- a/scripts/gdb/linux/utils.py +++ b/scripts/gdb/linux/utils.py @@ -123,6 +123,13 @@ def read_u64(buffer, offset): return read_u32(buffer, offset + 4) + (read_u32(buffer, offset) << 32) +def read_ulong(buffer, offset): + if get_long_type().sizeof == 8: + return read_u64(buffer, offset) + else: + return read_u32(buffer, offset) + + target_arch = None -- cgit v1.2.3 From e60768311af854734ce2bbfc50f24cff67b54a91 Mon Sep 17 00:00:00 2001 From: John Ogness Date: Fri, 14 Aug 2020 23:31:25 +0206 Subject: scripts/gdb: update for lockless printk ringbuffer With the introduction of the lockless printk ringbuffer, the data structure for the kernel log buffer was changed. Update the gdb scripts to be able to parse/print the new log buffer structure. Fixes: 896fbe20b4e2333fb55 ("printk: use the lockless ringbuffer") Signed-off-by: John Ogness Reported-by: Nick Desaulniers Tested-by: Nick Desaulniers Tested-by: Petr Mladek [akpm@linux-foundation.org: A typo fix.] Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20200814212525.6118-3-john.ogness@linutronix.de --- scripts/gdb/linux/dmesg.py | 139 +++++++++++++++++++++++++++++++++------------ 1 file changed, 102 insertions(+), 37 deletions(-) (limited to 'scripts/gdb/linux') diff --git a/scripts/gdb/linux/dmesg.py b/scripts/gdb/linux/dmesg.py index 2fa7bb83885f..6c6022012ea8 100644 --- a/scripts/gdb/linux/dmesg.py +++ b/scripts/gdb/linux/dmesg.py @@ -16,8 +16,13 @@ import sys from linux import utils -printk_log_type = utils.CachedType("struct printk_log") - +printk_info_type = utils.CachedType("struct printk_info") +prb_data_blk_lpos_type = utils.CachedType("struct prb_data_blk_lpos") +prb_desc_type = utils.CachedType("struct prb_desc") +prb_desc_ring_type = utils.CachedType("struct prb_desc_ring") +prb_data_ring_type = utils.CachedType("struct prb_data_ring") +printk_ringbuffer_type = utils.CachedType("struct printk_ringbuffer") +atomic_long_type = utils.CachedType("atomic_long_t") class LxDmesg(gdb.Command): """Print Linux kernel log buffer.""" @@ -26,44 +31,102 @@ class LxDmesg(gdb.Command): super(LxDmesg, self).__init__("lx-dmesg", gdb.COMMAND_DATA) def invoke(self, arg, from_tty): - log_buf_addr = int(str(gdb.parse_and_eval( - "(void *)'printk.c'::log_buf")).split()[0], 16) - log_first_idx = int(gdb.parse_and_eval("'printk.c'::log_first_idx")) - log_next_idx = int(gdb.parse_and_eval("'printk.c'::log_next_idx")) - log_buf_len = int(gdb.parse_and_eval("'printk.c'::log_buf_len")) - inf = gdb.inferiors()[0] - start = log_buf_addr + log_first_idx - if log_first_idx < log_next_idx: - log_buf_2nd_half = -1 - length = log_next_idx - log_first_idx - log_buf = utils.read_memoryview(inf, start, length).tobytes() - else: - log_buf_2nd_half = log_buf_len - log_first_idx - a = utils.read_memoryview(inf, start, log_buf_2nd_half) - b = utils.read_memoryview(inf, log_buf_addr, log_next_idx) - log_buf = a.tobytes() + b.tobytes() - - length_offset = printk_log_type.get_type()['len'].bitpos // 8 - text_len_offset = printk_log_type.get_type()['text_len'].bitpos // 8 - time_stamp_offset = printk_log_type.get_type()['ts_nsec'].bitpos // 8 - text_offset = printk_log_type.get_type().sizeof - - pos = 0 - while pos < log_buf.__len__(): - length = utils.read_u16(log_buf, pos + length_offset) - if length == 0: - if log_buf_2nd_half == -1: - gdb.write("Corrupted log buffer!\n") + + # read in prb structure + prb_addr = int(str(gdb.parse_and_eval("(void *)'printk.c'::prb")).split()[0], 16) + sz = printk_ringbuffer_type.get_type().sizeof + prb = utils.read_memoryview(inf, prb_addr, sz).tobytes() + + # read in descriptor ring structure + off = printk_ringbuffer_type.get_type()['desc_ring'].bitpos // 8 + addr = prb_addr + off + sz = prb_desc_ring_type.get_type().sizeof + desc_ring = utils.read_memoryview(inf, addr, sz).tobytes() + + # read in descriptor array + off = prb_desc_ring_type.get_type()['count_bits'].bitpos // 8 + desc_ring_count = 1 << utils.read_u32(desc_ring, off) + desc_sz = prb_desc_type.get_type().sizeof + off = prb_desc_ring_type.get_type()['descs'].bitpos // 8 + addr = utils.read_ulong(desc_ring, off) + descs = utils.read_memoryview(inf, addr, desc_sz * desc_ring_count).tobytes() + + # read in text data ring structure + off = printk_ringbuffer_type.get_type()['text_data_ring'].bitpos // 8 + addr = prb_addr + off + sz = prb_data_ring_type.get_type().sizeof + text_data_ring = utils.read_memoryview(inf, addr, sz).tobytes() + + # read in text data + off = prb_data_ring_type.get_type()['size_bits'].bitpos // 8 + text_data_sz = 1 << utils.read_u32(text_data_ring, off) + off = prb_data_ring_type.get_type()['data'].bitpos // 8 + addr = utils.read_ulong(text_data_ring, off) + text_data = utils.read_memoryview(inf, addr, text_data_sz).tobytes() + + counter_off = atomic_long_type.get_type()['counter'].bitpos // 8 + + sv_off = prb_desc_type.get_type()['state_var'].bitpos // 8 + + off = prb_desc_type.get_type()['text_blk_lpos'].bitpos // 8 + begin_off = off + (prb_data_blk_lpos_type.get_type()['begin'].bitpos // 8) + next_off = off + (prb_data_blk_lpos_type.get_type()['next'].bitpos // 8) + + off = prb_desc_type.get_type()['info'].bitpos // 8 + ts_off = off + printk_info_type.get_type()['ts_nsec'].bitpos // 8 + len_off = off + printk_info_type.get_type()['text_len'].bitpos // 8 + + # definitions from kernel/printk/printk_ringbuffer.h + desc_sv_bits = utils.get_long_type().sizeof * 8 + desc_committed_mask = 1 << (desc_sv_bits - 1) + desc_reuse_mask = 1 << (desc_sv_bits - 2) + desc_flags_mask = desc_committed_mask | desc_reuse_mask + desc_id_mask = ~desc_flags_mask + + # read in tail and head descriptor ids + off = prb_desc_ring_type.get_type()['tail_id'].bitpos // 8 + tail_id = utils.read_u64(desc_ring, off + counter_off) + off = prb_desc_ring_type.get_type()['head_id'].bitpos // 8 + head_id = utils.read_u64(desc_ring, off + counter_off) + + did = tail_id + while True: + ind = did % desc_ring_count + desc_off = desc_sz * ind + + # skip non-committed record + state = utils.read_u64(descs, desc_off + sv_off + counter_off) & desc_flags_mask + if state != desc_committed_mask: + if did == head_id: break - pos = log_buf_2nd_half + did = (did + 1) & desc_id_mask continue - text_len = utils.read_u16(log_buf, pos + text_len_offset) - text_start = pos + text_offset - text = log_buf[text_start:text_start + text_len].decode( - encoding='utf8', errors='replace') - time_stamp = utils.read_u64(log_buf, pos + time_stamp_offset) + begin = utils.read_ulong(descs, desc_off + begin_off) % text_data_sz + end = utils.read_ulong(descs, desc_off + next_off) % text_data_sz + + # handle data-less record + if begin & 1 == 1: + text = "" + else: + # handle wrapping data block + if begin > end: + begin = 0 + + # skip over descriptor id + text_start = begin + utils.get_long_type().sizeof + + text_len = utils.read_u16(descs, desc_off + len_off) + + # handle truncated message + if end - text_start < text_len: + text_len = end - text_start + + text = text_data[text_start:text_start + text_len].decode( + encoding='utf8', errors='replace') + + time_stamp = utils.read_u64(descs, desc_off + ts_off) for line in text.splitlines(): msg = u"[{time:12.6f}] {line}\n".format( @@ -75,7 +138,9 @@ class LxDmesg(gdb.Command): msg = msg.encode(encoding='utf8', errors='replace') gdb.write(msg) - pos += length + if did == head_id: + break + did = (did + 1) & desc_id_mask LxDmesg() -- cgit v1.2.3 From 10dcb06d40411a73e1ae111717e9a987bb760313 Mon Sep 17 00:00:00 2001 From: John Ogness Date: Mon, 14 Sep 2020 14:39:52 +0206 Subject: printk: ringbuffer: change representation of states Rather than deriving the state by evaluating bits within the flags area of the state variable, assign the states explicit values and set those values in the flags area. Introduce macros to make it simple to read and write state values for the state variable. Although the functionality is preserved, the binary representation for the states is changed. Signed-off-by: John Ogness Reviewed-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20200914123354.832-5-john.ogness@linutronix.de --- scripts/gdb/linux/dmesg.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) (limited to 'scripts/gdb/linux') diff --git a/scripts/gdb/linux/dmesg.py b/scripts/gdb/linux/dmesg.py index 6c6022012ea8..dd8c0b95063a 100644 --- a/scripts/gdb/linux/dmesg.py +++ b/scripts/gdb/linux/dmesg.py @@ -78,10 +78,10 @@ class LxDmesg(gdb.Command): len_off = off + printk_info_type.get_type()['text_len'].bitpos // 8 # definitions from kernel/printk/printk_ringbuffer.h + desc_committed = 1 desc_sv_bits = utils.get_long_type().sizeof * 8 - desc_committed_mask = 1 << (desc_sv_bits - 1) - desc_reuse_mask = 1 << (desc_sv_bits - 2) - desc_flags_mask = desc_committed_mask | desc_reuse_mask + desc_flags_shift = desc_sv_bits - 2 + desc_flags_mask = 3 << desc_flags_shift desc_id_mask = ~desc_flags_mask # read in tail and head descriptor ids @@ -96,8 +96,9 @@ class LxDmesg(gdb.Command): desc_off = desc_sz * ind # skip non-committed record - state = utils.read_u64(descs, desc_off + sv_off + counter_off) & desc_flags_mask - if state != desc_committed_mask: + state = 3 & (utils.read_u64(descs, desc_off + sv_off + + counter_off) >> desc_flags_shift) + if state != desc_committed: if did == head_id: break did = (did + 1) & desc_id_mask -- cgit v1.2.3 From 4cfc7258f876a7feba673ac6d050f525b39cc84c Mon Sep 17 00:00:00 2001 From: John Ogness Date: Mon, 14 Sep 2020 14:39:53 +0206 Subject: printk: ringbuffer: add finalization/extension support Add support for extending the newest data block. For this, introduce a new finalization state (desc_finalized) denoting a committed descriptor that cannot be extended. Until a record is finalized, a writer can reopen that record to append new data. Reopening a record means transitioning from the desc_committed state back to the desc_reserved state. A writer can explicitly finalize a record if there is no intention of extending it. Also, records are automatically finalized when a new record is reserved. This relieves writers of needing to explicitly finalize while also making such records available to readers sooner. (Readers can only traverse finalized records.) Four new memory barrier pairs are introduced. Two of them are insignificant additions (data_realloc:A/desc_read:D and data_realloc:A/data_push_tail:B) because they are alternate path memory barriers that exactly match the purpose, pairing, and context of the two existing memory barrier pairs they provide an alternate path for. The other two new memory barrier pairs are significant additions: desc_reopen_last:A / _prb_commit:B - When reopening a descriptor, ensure the state transitions back to desc_reserved before fully trusting the descriptor data. _prb_commit:B / desc_reserve:D - When committing a descriptor, ensure the state transitions to desc_committed before checking the head ID to see if the descriptor needs to be finalized. Signed-off-by: John Ogness Reviewed-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20200914123354.832-6-john.ogness@linutronix.de --- scripts/gdb/linux/dmesg.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) (limited to 'scripts/gdb/linux') diff --git a/scripts/gdb/linux/dmesg.py b/scripts/gdb/linux/dmesg.py index dd8c0b95063a..bce14de5f610 100644 --- a/scripts/gdb/linux/dmesg.py +++ b/scripts/gdb/linux/dmesg.py @@ -79,6 +79,7 @@ class LxDmesg(gdb.Command): # definitions from kernel/printk/printk_ringbuffer.h desc_committed = 1 + desc_finalized = 2 desc_sv_bits = utils.get_long_type().sizeof * 8 desc_flags_shift = desc_sv_bits - 2 desc_flags_mask = 3 << desc_flags_shift @@ -98,7 +99,7 @@ class LxDmesg(gdb.Command): # skip non-committed record state = 3 & (utils.read_u64(descs, desc_off + sv_off + counter_off) >> desc_flags_shift) - if state != desc_committed: + if state != desc_committed and state != desc_finalized: if did == head_id: break did = (did + 1) & desc_id_mask -- cgit v1.2.3 From 74caba7f2a0685575b3ee5330a118f5922485e02 Mon Sep 17 00:00:00 2001 From: John Ogness Date: Mon, 21 Sep 2020 13:24:45 +0206 Subject: printk: move dictionary keys to dev_printk_info Dictionaries are only used for SUBSYSTEM and DEVICE properties. The current implementation stores the property names each time they are used. This requires more space than otherwise necessary. Also, because the dictionary entries are currently considered optional, it cannot be relied upon that they are always available, even if the writer wanted to store them. These issues will increase should new dictionary properties be introduced. Rather than storing the subsystem and device properties in the dict ring, introduce a struct dev_printk_info with separate fields to store only the property values. Embed this struct within the struct printk_info to provide guaranteed availability. Signed-off-by: John Ogness Reviewed-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/87mu1jl6ne.fsf@jogness.linutronix.de --- scripts/gdb/linux/dmesg.py | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) (limited to 'scripts/gdb/linux') diff --git a/scripts/gdb/linux/dmesg.py b/scripts/gdb/linux/dmesg.py index bce14de5f610..a92c55bd8de5 100644 --- a/scripts/gdb/linux/dmesg.py +++ b/scripts/gdb/linux/dmesg.py @@ -52,6 +52,12 @@ class LxDmesg(gdb.Command): addr = utils.read_ulong(desc_ring, off) descs = utils.read_memoryview(inf, addr, desc_sz * desc_ring_count).tobytes() + # read in info array + info_sz = printk_info_type.get_type().sizeof + off = prb_desc_ring_type.get_type()['infos'].bitpos // 8 + addr = utils.read_ulong(desc_ring, off) + infos = utils.read_memoryview(inf, addr, info_sz * desc_ring_count).tobytes() + # read in text data ring structure off = printk_ringbuffer_type.get_type()['text_data_ring'].bitpos // 8 addr = prb_addr + off @@ -73,9 +79,8 @@ class LxDmesg(gdb.Command): begin_off = off + (prb_data_blk_lpos_type.get_type()['begin'].bitpos // 8) next_off = off + (prb_data_blk_lpos_type.get_type()['next'].bitpos // 8) - off = prb_desc_type.get_type()['info'].bitpos // 8 - ts_off = off + printk_info_type.get_type()['ts_nsec'].bitpos // 8 - len_off = off + printk_info_type.get_type()['text_len'].bitpos // 8 + ts_off = printk_info_type.get_type()['ts_nsec'].bitpos // 8 + len_off = printk_info_type.get_type()['text_len'].bitpos // 8 # definitions from kernel/printk/printk_ringbuffer.h desc_committed = 1 @@ -95,6 +100,7 @@ class LxDmesg(gdb.Command): while True: ind = did % desc_ring_count desc_off = desc_sz * ind + info_off = info_sz * ind # skip non-committed record state = 3 & (utils.read_u64(descs, desc_off + sv_off + @@ -119,7 +125,7 @@ class LxDmesg(gdb.Command): # skip over descriptor id text_start = begin + utils.get_long_type().sizeof - text_len = utils.read_u16(descs, desc_off + len_off) + text_len = utils.read_u16(infos, info_off + len_off) # handle truncated message if end - text_start < text_len: @@ -128,7 +134,7 @@ class LxDmesg(gdb.Command): text = text_data[text_start:text_start + text_len].decode( encoding='utf8', errors='replace') - time_stamp = utils.read_u64(descs, desc_off + ts_off) + time_stamp = utils.read_u64(infos, info_off + ts_off) for line in text.splitlines(): msg = u"[{time:12.6f}] {line}\n".format( -- cgit v1.2.3