joel16/android_kernel_sony_msm8994
1
0
Fork 0
mirror of https://github.com/joel16/android_kernel_sony_msm8994.git synced 2024-11-23 12:10:29 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

printk: introduce printk oops log buffer

Browse Source 
The initial kernel oops message often contains informative log messages
to help root cause issues.  However, because of a limited log buffer size,
it is possible that important information is lost due to log buffer
wrap-around.

Introduce oops log buffer which preserves kernel messages from the point
when kernel oops happened by saving messages from regular log buffer when
the initial oops messages wrap arounds.
This guarantees to obtain initial oops and onward messages up to configured
buffer size by running dmesg, /dev/kmsg, /proc/kmsg, kmsg_dumper and other
debugging tools.

Below is a dmesg output example with CONFIG_OOPS_LOG_BUFFER=y after kernel
oops that shows the kernel oops and onward messages up to oops log buffer
while regular log buffer still shows the newest messages with
distinguishing line '---end of oops log buffer---'.

Internal error: Oops: a07 [#1] PREEMPT SMP ARM
Modules linked in:
CPU: 0 PID: 192 Comm: sh Tainted: G        W    3.10.0-gd727407-00072-g7c16272-dirty #87
task: c457ca80 ti: c45dc000 task.ti: c45dc000
PC is at sysrq_handle_crash+0xc/0x14
LR is at write_sysrq_trigger+0x40/0x50
pc : [<c05420ec>]    lr : [<c0542a00>]    psr: 40000013
sp : c45ddf30  ip : fffff100  fp : 0015ab14
r10: 00000000  r9 : 00000002  r8 : 0015bc68
r7 : 00000000  r6 : 00000001  r5 : 0015bc68  r4 : 00000002
r3 : 00000000  r2 : 00000001  r1 : 60000013  r0 : 00000063
Flags: nZcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 30c5787d  Table: 045673c0  DAC: fffffffd
<snip>
LR: 0xc0542980:
2980  1a000004 e1a00006 e2841034 ebfd8a4d e2707001 33a07000 e1a00007 e28dd004
29a0  e8bd8ff0 c0c41220 c14bfda8 c162a004 c162a008 c146a450 c162a034 c14640c0
29c0  e92d4070 e2524000 0a00000c e1a05001 ebf7b96c e1a0200d e1a00005 e3c23d7f
---end of oops log buffer---
lowmem_reserve[]: 0 9968 9968
HighMem free:1256224kB min:512kB low:2044kB high:3580kB active_anon:132kB inactive_anon:0kB active_file:508kB io
lowmem_reserve[]: 0 0 0
Normal: 9*4kB (UM) 10*8kB (UEM) 6*16kB (UEM) 6*32kB (UEM) 6*64kB (UM) 9*128kB (UEM) 7*256kB (UM) 8*512kB (UM) 7B
HighMem: 0*4kB 2*8kB (UM) 1*16kB (U) 2*32kB (UC) 1*64kB (C) 1*128kB (C) 2*256kB (MC) 2*512kB (MC) 3*1024kB (UMCB
364 total pagecache pages
<snip>

CRs-fixed: 561659
Change-Id: I587961931bfea3aba64a40790598020a4d5b9b36
Signed-off-by: Joonwoo Park <joonwoop@codeaurora.org>
This commit is contained in:
Joonwoo Park 2014-02-21 12:20:50 -08:00
parent a8f114ccd9
commit 12929e77d4
4 changed files with 348 additions and 47 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
include/linux/printk.h
View File

@ -397,4 +397,12 @@ static inline void print_hex_dump_bytes(const char *prefix_str, int prefix_type,
groupsize, buf, len, ascii)
#endif /* defined(CONFIG_DYNAMIC_DEBUG) */
#if defined(CONFIG_OOPS_LOG_BUFFER)
extern void oops_printk_start(void);
#else
static inline void oops_printk_start(void)
{
}
#endif
#endif

1
kernel/panic.c
View File

@ -361,6 +361,7 @@ void oops_enter(void)
tracing_off();
/* can't trust the integrity of the kernel anymore: */
debug_locks_off();
oops_printk_start();
do_oops_enter_exit();
}

363
kernel/printk.c
View File

@ -255,6 +255,23 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
static char *log_buf = __log_buf;
static u32 log_buf_len = __LOG_BUF_LEN;
#if defined(CONFIG_OOPS_LOG_BUFFER)
#define __OOPS_LOG_BUF_LEN (1 << CONFIG_OOPS_LOG_BUF_SHIFT)
static char __log_oops_buf[__OOPS_LOG_BUF_LEN] __aligned(LOG_ALIGN);
static char *log_oops_buf = __log_oops_buf;
static u32 log_oops_buf_len = __OOPS_LOG_BUF_LEN;
static int log_oops_full;
/* if this sequence of log entry starts to wrap arounds, move to oops buffer */
static u64 log_oops_first_seq = ULLONG_MAX;
static u64 log_oops_last_seq;
static u32 log_oops_next_idx;
static u32 syslog_oops_buf_idx;
static const char log_oops_end[] = "---end of oops log buffer---";
#endif
/* cpu currently holding logbuf_lock */
static volatile unsigned int logbuf_cpu = UINT_MAX;
@ -271,23 +288,41 @@ static char *log_dict(const struct log *msg)
}
/* get record by index; idx must point to valid msg */
static struct log *log_from_idx(u32 idx)
static struct log *log_from_idx(u32 idx, bool logbuf)
{
struct log *msg = (struct log *)(log_buf + idx);
struct log *msg;
char *buf;
#if defined(CONFIG_OOPS_LOG_BUFFER)
buf = logbuf ? log_buf : log_oops_buf;
#else
buf = log_buf;
BUG_ON(!logbuf);
#endif
msg = (struct log *)(buf + idx);
/*
* A length == 0 record is the end of buffer marker. Wrap around and
* read the message at the start of the buffer.
*/
if (!msg->len)
return (struct log *)log_buf;
return (struct log *)buf;
return msg;
}
/* get next record; idx must point to valid msg */
static u32 log_next(u32 idx)
static u32 log_next(u32 idx, bool logbuf)
{
struct log *msg = (struct log *)(log_buf + idx);
struct log *msg;
char *buf;
#if defined(CONFIG_OOPS_LOG_BUFFER)
buf = logbuf ? log_buf : log_oops_buf;
#else
buf = log_buf;
BUG_ON(!logbuf);
#endif
msg = (struct log *)(buf + idx);
/* length == 0 indicates the end of the buffer; wrap */
/*
@ -296,12 +331,65 @@ static u32 log_next(u32 idx)
* return the one after that.
*/
if (!msg->len) {
msg = (struct log *)log_buf;
msg = (struct log *)buf;
return msg->len;
}
return idx + msg->len;
}
#if defined(CONFIG_OOPS_LOG_BUFFER)
void oops_printk_start(void)
{
raw_spin_lock_irq(&logbuf_lock);
if (log_oops_first_seq == ULLONG_MAX)
log_oops_first_seq = log_next_seq;
raw_spin_unlock_irq(&logbuf_lock);
}
static void log_oops_store(struct log *msg)
{
u32 free;
const int eom_len = strlen(log_oops_end);
const size_t eom_size = sizeof(struct log) + eom_len;
char buf[eom_size + LOG_ALIGN];
u32 pad_len;
u64 ts_nsec;
int eom = 0;
if (log_first_seq >= log_oops_first_seq && !log_oops_full) {
free = log_oops_buf_len - log_oops_next_idx;
pad_len = (-eom_size) & (LOG_ALIGN - 1);
if ((free - msg->len) < (eom_size + pad_len)) {
ts_nsec = msg->ts_nsec;
msg = (struct log *)buf;
memcpy(log_text(msg), log_oops_end, eom_len);
msg->len = eom_size + pad_len;
msg->text_len = eom_len;
msg->dict_len = 0;
msg->facility = 1;
msg->level = default_message_loglevel & 7;
msg->flags = (LOG_NEWLINE | LOG_PREFIX) & 0x1f;
msg->ts_nsec = ts_nsec;
eom = 1;
}
if (free >= msg->len) {
memcpy(log_oops_buf + log_oops_next_idx, msg, msg->len);
log_oops_next_idx += msg->len;
log_oops_last_seq = log_first_seq;
if (eom)
log_oops_full = 1;
} else {
log_oops_full = 1;
}
}
}
#else
static void log_oops_store(struct log *msg)
{
}
#endif
/* insert record into the buffer, discard old ones, update heads */
static void log_store(int facility, int level,
enum log_flags flags, u64 ts_nsec,
@ -327,8 +415,11 @@ static void log_store(int facility, int level,
if (free > size + sizeof(struct log))
break;
msg = (struct log *)(log_buf + log_first_idx);
log_oops_store(msg);
/* drop old messages until we have enough contiuous space */
log_first_idx = log_next(log_first_idx);
log_first_idx = log_next(log_first_idx, true);
log_first_seq++;
}
@ -475,6 +566,23 @@ out:
return ret;
}
#if defined(CONFIG_OOPS_LOG_BUFFER)
static bool devkmsg_seq_passed(struct devkmsg_user *user)
{
if ((log_oops_first_seq == ULLONG_MAX && user->seq < log_first_seq) ||
(log_oops_first_seq != ULLONG_MAX &&
user->seq < log_oops_first_seq))
return true;
else
return false;
}
#else
static bool devkmsg_seq_passed(struct devkmsg_user *user)
{
return user->seq < log_first_seq;
}
#endif
static ssize_t devkmsg_read(struct file *file, char __user *buf,
size_t count, loff_t *ppos)
{
@ -485,6 +593,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
char cont = '-';
size_t len;
ssize_t ret;
bool regular_buf = true;
if (!user)
return -EBADF;
@ -508,7 +617,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
raw_spin_lock_irq(&logbuf_lock);
}
if (user->seq < log_first_seq) {
if (devkmsg_seq_passed(user)) {
/* our last seen message is gone, return error and reset */
user->idx = log_first_idx;
user->seq = log_first_seq;
@ -516,8 +625,22 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
raw_spin_unlock_irq(&logbuf_lock);
goto out;
}
#if defined(CONFIG_OOPS_LOG_BUFFER)
else if (log_oops_first_seq != ULLONG_MAX) {
if (user->seq <= log_oops_first_seq) {
user->idx = 0;
regular_buf = false;
} else if (user->seq > log_oops_first_seq &&
user->seq < log_oops_last_seq) {
regular_buf = false;
} else if (user->seq < log_first_seq) {
user->idx = log_first_idx;
user->seq = log_first_seq;
}
}
#endif
msg = log_from_idx(user->idx);
msg = log_from_idx(user->idx, regular_buf);
ts_usec = msg->ts_nsec;
do_div(ts_usec, 1000);
@ -578,7 +701,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
user->buf[len++] = '\n';
}
user->idx = log_next(user->idx);
user->idx = log_next(user->idx, regular_buf);
user->seq++;
raw_spin_unlock_irq(&logbuf_lock);
@ -597,6 +720,20 @@ out:
return ret;
}
static void devkmsg_set_first(struct devkmsg_user *user)
{
#if defined(CONFIG_OOPS_LOG_BUFFER)
if (log_oops_first_seq != ULLONG_MAX) {
user->idx = 0;
user->seq = log_oops_first_seq;
} else
#endif
{
user->idx = log_first_idx;
user->seq = log_first_seq;
}
}
static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
{
struct devkmsg_user *user = file->private_data;
@ -611,8 +748,7 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
switch (whence) {
case SEEK_SET:
/* the first record */
user->idx = log_first_idx;
user->seq = log_first_seq;
devkmsg_set_first(user);
break;
case SEEK_DATA:
/*
@ -679,8 +815,7 @@ static int devkmsg_open(struct inode *inode, struct file *file)
mutex_init(&user->lock);
raw_spin_lock_irq(&logbuf_lock);
user->idx = log_first_idx;
user->seq = log_first_seq;
devkmsg_set_first(user);
raw_spin_unlock_irq(&logbuf_lock);
file->private_data = user;
@ -966,16 +1101,132 @@ static size_t msg_print_text(const struct log *msg, enum log_flags prev,
return len;
}
static int syslog_print(char __user *buf, int size)
#if defined(CONFIG_OOPS_LOG_BUFFER)
static int syslog_oops_buf_print(char __user *buf, int size, char *text)
{
struct log *msg;
size_t n;
size_t skip;
int len = 0;
raw_spin_lock_irq(&logbuf_lock);
if (syslog_seq < log_oops_first_seq) {
syslog_seq = log_oops_first_seq;
syslog_oops_buf_idx = 0;
}
while (size > 0 && log_oops_last_seq > syslog_seq) {
skip = syslog_partial;
msg = log_from_idx(syslog_oops_buf_idx, false);
n = msg_print_text(msg, syslog_prev, true, text,
LOG_LINE_MAX + PREFIX_MAX);
if (n - syslog_partial <= size) {
/* message fits into buffer, move forward */
syslog_oops_buf_idx = log_next(syslog_oops_buf_idx,
false);
syslog_seq++;
syslog_prev = msg->flags;
n -= syslog_partial;
syslog_partial = 0;
} else if (!len) {
/* partial read(), remember position */
n = size;
syslog_partial += n;
} else {
n = 0;
}
if (!n)
break;
raw_spin_unlock_irq(&logbuf_lock);
if (copy_to_user(buf, text + skip, n)) {
raw_spin_lock_irq(&logbuf_lock);
if (!len)
len = -EFAULT;
break;
}
raw_spin_lock_irq(&logbuf_lock);
len += n;
size -= n;
buf += n;
}
raw_spin_unlock_irq(&logbuf_lock);
return len;
}
static int syslog_print_oops_buf_all(char __user *buf, int size, bool clear,
char *text)
{
int len = 0;
u32 idx = 0;
u64 seq = clear_seq;
enum log_flags prev = 0;
u64 next_seq;
if (!buf)
return len;
raw_spin_lock_irq(&logbuf_lock);
seq = log_oops_first_seq;
next_seq = log_oops_last_seq;
while (len >= 0 && len < size && seq < next_seq) {
struct log *msg = log_from_idx(idx, false);
int textlen;
textlen = msg_print_text(msg, prev, true, text,
LOG_LINE_MAX + PREFIX_MAX);
if (textlen < 0) {
len = textlen;
break;
}
idx = log_next(idx, false);
seq++;
prev = msg->flags;
raw_spin_unlock_irq(&logbuf_lock);
if (copy_to_user(buf + len, text, textlen))
len = -EFAULT;
else
len += textlen;
raw_spin_lock_irq(&logbuf_lock);
}
raw_spin_unlock_irq(&logbuf_lock);
return len;
}
#else
static int syslog_oops_buf_print(char __user *buf, int size, char *text)
{
return 0;
}
static int syslog_print_oops_buf_all(char __user *buf, int size, bool clear,
char *text)
{
return 0;
}
#endif
int syslog_print(char __user *buf, int size)
{
char *text;
struct log *msg;
int oops_buf_len;
int len = 0;
text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
if (!text)
return -ENOMEM;
oops_buf_len = syslog_oops_buf_print(buf, size, text);
if (oops_buf_len < 0)
return oops_buf_len;
size -= oops_buf_len;
while (size > 0) {
size_t n;
size_t skip;
@ -994,12 +1245,12 @@ static int syslog_print(char __user *buf, int size)
}
skip = syslog_partial;
msg = log_from_idx(syslog_idx);
msg = log_from_idx(syslog_idx, true);
n = msg_print_text(msg, syslog_prev, true, text,
LOG_LINE_MAX + PREFIX_MAX);
if (n - syslog_partial <= size) {
/* message fits into buffer, move forward */
syslog_idx = log_next(syslog_idx);
syslog_idx = log_next(syslog_idx, true);
syslog_seq++;
syslog_prev = msg->flags;
n -= syslog_partial;
@ -1015,7 +1266,7 @@ static int syslog_print(char __user *buf, int size)
if (!n)
break;
if (copy_to_user(buf, text + skip, n)) {
if (copy_to_user(buf + oops_buf_len, text + skip, n)) {
if (!len)
len = -EFAULT;
break;
@ -1027,57 +1278,69 @@ static int syslog_print(char __user *buf, int size)
}
kfree(text);
if (len > 0)
len += oops_buf_len;
return len;
}
static int syslog_print_all(char __user *buf, int size, bool clear)
{
char *text;
int oops_len;
int len = 0;
text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
if (!text)
return -ENOMEM;
oops_len = syslog_print_oops_buf_all(buf, size, clear, text);
if (oops_len < 0)
return oops_len;
raw_spin_lock_irq(&logbuf_lock);
if (buf) {
u64 next_seq;
u64 seq;
u32 idx;
u64 start_seq;
u32 start_idx;
enum log_flags prev;
if (clear_seq < log_first_seq) {
/* messages are gone, move to first available one */
clear_seq = log_first_seq;
clear_idx = log_first_idx;
start_seq = log_first_seq;
start_idx = log_first_idx;
} else {
start_seq = clear_seq;
start_idx = clear_idx;
}
/*
* Find first record that fits, including all following records,
* into the user-provided buffer for this dump.
*/
seq = clear_seq;
idx = clear_idx;
seq = start_seq;
idx = start_idx;
prev = 0;
while (seq < log_next_seq) {
struct log *msg = log_from_idx(idx);
struct log *msg = log_from_idx(idx, true);
len += msg_print_text(msg, prev, true, NULL, 0);
prev = msg->flags;
idx = log_next(idx);
idx = log_next(idx, true);
seq++;
}
/* move first record forward until length fits into the buffer */
seq = clear_seq;
idx = clear_idx;
seq = start_seq;
idx = start_idx;
prev = 0;
while (len > size && seq < log_next_seq) {
struct log *msg = log_from_idx(idx);
while ((len > size - oops_len) && seq < log_next_seq) {
struct log *msg = log_from_idx(idx, true);
len -= msg_print_text(msg, prev, true, NULL, 0);
prev = msg->flags;
idx = log_next(idx);
idx = log_next(idx, true);
seq++;
}
@ -1087,7 +1350,7 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
len = 0;
prev = 0;
while (len >= 0 && seq < next_seq) {
struct log *msg = log_from_idx(idx);
struct log *msg = log_from_idx(idx, true);
int textlen;
textlen = msg_print_text(msg, prev, true, text,
@ -1096,12 +1359,12 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
len = textlen;
break;
}
idx = log_next(idx);
idx = log_next(idx, true);
seq++;
prev = msg->flags;
raw_spin_unlock_irq(&logbuf_lock);
if (copy_to_user(buf + len, text, textlen))
if (copy_to_user(buf + len + oops_len, text, textlen))
len = -EFAULT;
else
len += textlen;
@ -1123,6 +1386,8 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
raw_spin_unlock_irq(&logbuf_lock);
kfree(text);
if (len > 0)
len += oops_len;
return len;
}
@ -1233,10 +1498,11 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
error = 0;
while (seq < log_next_seq) {
struct log *msg = log_from_idx(idx);
struct log *msg = log_from_idx(idx,
true);
error += msg_print_text(msg, prev, true, NULL, 0);
idx = log_next(idx);
idx = log_next(idx, true);
seq++;
prev = msg->flags;
}
@ -1247,6 +1513,9 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
/* Size of the log buffer */
case SYSLOG_ACTION_SIZE_BUFFER:
error = log_buf_len;
#if defined(CONFIG_OOPS_LOG_BUFFER)
error += log_oops_buf_len;
#endif
break;
default:
error = -EINVAL;
@ -1719,8 +1988,8 @@ static struct cont {
u8 level;
bool flushed:1;
} cont;
static struct log *log_from_idx(u32 idx) { return NULL; }
static u32 log_next(u32 idx) { return 0; }
static struct log *log_from_idx(u32 idx, bool logbuf) { return NULL; }
static u32 log_next(u32 idx, bool logbuf) { return 0; }
static void call_console_drivers(int level, const char *text, size_t len) {}
static size_t msg_print_text(const struct log *msg, enum log_flags prev,
bool syslog, char *buf, size_t size) { return 0; }
@ -2084,13 +2353,13 @@ skip:
if (console_seq == log_next_seq)
break;
msg = log_from_idx(console_idx);
msg = log_from_idx(console_idx, true);
if (msg->flags & LOG_NOCONS) {
/*
* Skip record we have buffered and already printed
* directly to the console when we received it.
*/
console_idx = log_next(console_idx);
console_idx = log_next(console_idx, true);
console_seq++;
/*
* We will get here again when we register a new
@ -2105,7 +2374,7 @@ skip:
level = msg->level;
len = msg_print_text(msg, console_prev, false,
text, sizeof(text));
console_idx = log_next(console_idx);
console_idx = log_next(console_idx, true);
console_seq++;
console_prev = msg->flags;
raw_spin_unlock(&logbuf_lock);
@ -2701,10 +2970,10 @@ bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog,
if (dumper->cur_seq >= log_next_seq)
goto out;
msg = log_from_idx(dumper->cur_idx);
msg = log_from_idx(dumper->cur_idx, true);
l = msg_print_text(msg, 0, syslog, line, size);
dumper->cur_idx = log_next(dumper->cur_idx);
dumper->cur_idx = log_next(dumper->cur_idx, true);
dumper->cur_seq++;
ret = true;
out:
@ -2796,10 +3065,10 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
idx = dumper->cur_idx;
prev = 0;
while (seq < dumper->next_seq) {
struct log *msg = log_from_idx(idx);
struct log *msg = log_from_idx(idx, true);
l += msg_print_text(msg, prev, true, NULL, 0);
idx = log_next(idx);
idx = log_next(idx, true);
seq++;
prev = msg->flags;
}
@ -2809,10 +3078,10 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
idx = dumper->cur_idx;
prev = 0;
while (l > size && seq < dumper->next_seq) {
struct log *msg = log_from_idx(idx);
struct log *msg = log_from_idx(idx, true);
l -= msg_print_text(msg, prev, true, NULL, 0);
idx = log_next(idx);
idx = log_next(idx, true);
seq++;
prev = msg->flags;
}
@ -2824,10 +3093,10 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
l = 0;
prev = 0;
while (seq < dumper->next_seq) {
struct log *msg = log_from_idx(idx);
struct log *msg = log_from_idx(idx, true);
l += msg_print_text(msg, prev, syslog, buf + l, size - l);
idx = log_next(idx);
idx = log_next(idx, true);
seq++;
prev = msg->flags;
}

23
lib/Kconfig.debug
View File

@ -1480,6 +1480,29 @@ config DYNAMIC_DEBUG
See Documentation/dynamic-debug-howto.txt for additional information.
config OOPS_LOG_BUFFER
bool "Enable printk() oops log buffer"
depends on PRINTK
help
Select this option to create a seperate log buffer which doesn't
allow wrap around but preserve the first oops and onward kernel
messages until buffer becomes full.
config OOPS_LOG_BUF_SHIFT
int "Oops log buffer size (16 => 64KB, 17 => 128KB)"
depends on OOPS_LOG_BUFFER
range 11 21
default 13
help
Select Oops log buffer size as a power of 2.
Examples:
17 => 128 KB
16 => 64 KB
15 => 32 KB
14 => 16 KB
13 => 8 KB
12 => 4 KB
config DMA_API_DEBUG
bool "Enable debugging of DMA-API usage"
depends on HAVE_DMA_API_DEBUG