Commit e6076831 authored by John Ogness's avatar John Ogness Committed by Petr Mladek
Browse files

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: 896fbe20 ("printk: use the lockless ringbuffer")
Signed-off-by: default avatarJohn Ogness <john.ogness@linutronix.de>
Reported-by: default avatarNick Desaulniers <ndesaulniers@google.com>
Tested-by: default avatarNick Desaulniers <ndesaulniers@google.com>
Tested-by: default avatarPetr Mladek <pmladek@suse.com>
[akpm@linux-foundation.org: A typo fix.]
Signed-off-by: default avatarPetr Mladek <pmladek@suse.com>
Link: https://lore.kernel.org/r/20200814212525.6118-3-john.ogness@linutronix.de
parent 3e0d075c

Documentation/admin-guide/kdump/gdbmacros.txt

+107 −46
Original line number Diff line number Diff line
@@ -170,57 +170,111 @@ document trapinfo 
	address the kernel panicked.

end



define dump_log_idx

	set $idx = $arg0

define dump_record

	set var $desc = $arg0

	if ($argc > 1)

		set $prev_flags = $arg1

		set var $prev_flags = $arg1

	else

		set $prev_flags = 0

		set var $prev_flags = 0

	end

	set $msg = ((struct printk_log *) (log_buf + $idx))

	set $prefix = 1

	set $newline = 1

	set $log = log_buf + $idx + sizeof(*$msg)



	# prev & LOG_CONT && !(msg->flags & LOG_PREIX)

	if (($prev_flags & 8) && !($msg->flags & 4))

		set $prefix = 0

	set var $info = &$desc->info

	set var $prefix = 1

	set var $newline = 1



	set var $begin = $desc->text_blk_lpos.begin % (1U << prb->text_data_ring.size_bits)

	set var $next = $desc->text_blk_lpos.next % (1U << prb->text_data_ring.size_bits)



	# handle data-less record

	if ($begin & 1)

		set var $text_len = 0

		set var $log = ""

	else

		# handle wrapping data block

		if ($begin > $next)

			set var $begin = 0

		end



		# skip over descriptor id

		set var $begin = $begin + sizeof(long)



		# handle truncated message

		if ($next - $begin < $info->text_len)

			set var $text_len = $next - $begin

		else

			set var $text_len = $info->text_len

		end



	# msg->flags & LOG_CONT

	if ($msg->flags & 8)

		set var $log = &prb->text_data_ring.data[$begin]

	end



	# prev & LOG_CONT && !(info->flags & LOG_PREIX)

	if (($prev_flags & 8) && !($info->flags & 4))

		set var $prefix = 0

	end



	# info->flags & LOG_CONT

	if ($info->flags & 8)

		# (prev & LOG_CONT && !(prev & LOG_NEWLINE))

		if (($prev_flags & 8) && !($prev_flags & 2))

			set $prefix = 0

			set var $prefix = 0

		end

		# (!(msg->flags & LOG_NEWLINE))

		if (!($msg->flags & 2))

			set $newline = 0

		# (!(info->flags & LOG_NEWLINE))

		if (!($info->flags & 2))

			set var $newline = 0

		end

	end



	if ($prefix)

		printf "[%5lu.%06lu] ", $msg->ts_nsec / 1000000000, $msg->ts_nsec % 1000000000

		printf "[%5lu.%06lu] ", $info->ts_nsec / 1000000000, $info->ts_nsec % 1000000000

	end

	if ($msg->text_len != 0)

		eval "printf \"%%%d.%ds\", $log", $msg->text_len, $msg->text_len

	if ($text_len)

		eval "printf \"%%%d.%ds\", $log", $text_len, $text_len

	end

	if ($newline)

		printf "\n"

	end

	if ($msg->dict_len > 0)

		set $dict = $log + $msg->text_len

		set $idx = 0

		set $line = 1

		while ($idx < $msg->dict_len)



	# handle dictionary data



	set var $begin = $desc->dict_blk_lpos.begin % (1U << prb->dict_data_ring.size_bits)

	set var $next = $desc->dict_blk_lpos.next % (1U << prb->dict_data_ring.size_bits)



	# handle data-less record

	if ($begin & 1)

		set var $dict_len = 0

		set var $dict = ""

	else

		# handle wrapping data block

		if ($begin > $next)

			set var $begin = 0

		end



		# skip over descriptor id

		set var $begin = $begin + sizeof(long)



		# handle truncated message

		if ($next - $begin < $info->dict_len)

			set var $dict_len = $next - $begin

		else

			set var $dict_len = $info->dict_len

		end



		set var $dict = &prb->dict_data_ring.data[$begin]

	end



	if ($dict_len > 0)

		set var $idx = 0

		set var $line = 1

		while ($idx < $dict_len)

			if ($line)

				printf " "

				set $line = 0

				set var $line = 0

			end

			set $c = $dict[$idx]

			set var $c = $dict[$idx]

			if ($c == '\0')

				printf "\n"

				set $line = 1

				set var $line = 1

			else

				if ($c < ' ' || $c >= 127 || $c == '\\')

					printf "\\x%02x", $c
@@ -228,33 +282,40 @@ define dump_log_idx 
					printf "%c", $c

				end

			end

			set $idx = $idx + 1

			set var $idx = $idx + 1

		end

		printf "\n"

	end

end

document dump_log_idx

	Dump a single log given its index in the log buffer.  The first

	parameter is the index into log_buf, the second is optional and

	specified the previous log buffer's flags, used for properly

	formatting continued lines.

document dump_record

	Dump a single record. The first parameter is the descriptor

	sequence number, the second is optional and specifies the

	previous record's flags, used for properly formatting

	continued lines.

end



define dmesg

	set $i = log_first_idx

	set $end_idx = log_first_idx

	set $prev_flags = 0

	set var $desc_committed = 1UL << ((sizeof(long) * 8) - 1)

	set var $flags_mask = 3UL << ((sizeof(long) * 8) - 2)

	set var $id_mask = ~$flags_mask



	set var $desc_count = 1U << prb->desc_ring.count_bits

	set var $prev_flags = 0



	set var $id = prb->desc_ring.tail_id.counter

	set var $end_id = prb->desc_ring.head_id.counter



	while (1)

		set $msg = ((struct printk_log *) (log_buf + $i))

		if ($msg->len == 0)

			set $i = 0

		else

			dump_log_idx $i $prev_flags

			set $i = $i + $msg->len

			set $prev_flags = $msg->flags

		set var $desc = &prb->desc_ring.descs[$id % $desc_count]



		# skip non-committed record

		if (($desc->state_var.counter & $flags_mask) == $desc_committed)

			dump_record $desc $prev_flags

			set var $prev_flags = $desc->info.flags

		end

		if ($i == $end_idx)



		set var $id = ($id + 1) & $id_mask

		if ($id == $end_id)

			loop_break

		end

	end

scripts/gdb/linux/dmesg.py

+102 −37
Original line number Diff line number Diff line
@@ -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(

            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(log_buf, pos + time_stamp_offset)



            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()