Debugging
Kernel panic occurs at 68 line inside __list_del_entry() whose caller function is process_one_work().
Code Review at the moment of kernel panic
49void __list_del_entry(struct list_head *entry)
50{
51 struct list_head *prev, *next;
52
53 prev = entry->prev;
54 next = entry->next;
55
56 if (WARN(next == LIST_POISON1,
57 "list_del corruption, %p->next is LIST_POISON1 (%p)\n",
58 entry, LIST_POISON1) ||
59 WARN(prev == LIST_POISON2,
60 "list_del corruption, %p->prev is LIST_POISON2 (%p)\n",
61 entry, LIST_POISON2) ||
62 WARN(prev->next != entry,
63 "list_del corruption. prev->next should be %p, "
64 "but was %p\n", entry, prev->next) ||
65 WARN(next->prev != entry,
66 "list_del corruption. next->prev should be %p, "
67 "but was %p\n", entry, next->prev)) {
68 BUG_ON(PANIC_CORRUPTION); // <<-- kernel panic
69 return;
70 }
71
72 __list_del(prev, next);
73}
Callstacks
-000|do_undefinstr(regs = 0x0)
-001|__und_svc_fault(asm)
-->|exception
-002|__list_del_entry(?) // <<-- kernel panic
-003|process_one_work(worker = 0xEC048600, work = 0xEA2585AC)
-004|worker_thread(__worker = 0x0)
-005|kthread(_create = 0xEB9B3000)
-006|ret_from_fork(asm)
-007|ret_fast_syscall(asm)
The list_del_init() is called inside process_one_work() whose parameter is &work->entry.
Now, it is important to debug the state of &work->entry
static void process_one_work(struct worker *worker, struct work_struct *work)
__releases(&pool->lock)
__acquires(&pool->lock)
{
struct pool_workqueue *pwq = get_work_pwq(work);
struct worker_pool *pool = worker->pool;
bool cpu_intensive = pwq->wq->flags & WQ_CPU_INTENSIVE;
int work_color;
struct worker *collision;
//snip
/* claim and dequeue */
debug_work_deactivate(work);
hash_add(pool->busy_hash, &worker->hentry, (unsigned long)work);
worker->current_work = work;
worker->current_func = work->func;
worker->current_pwq = pwq;
work_color = get_work_color(work);
list_del_init(&work->entry);
Going back to process_one_work() function frame using T32, I can have the following debug information
[1],[2]: next element is corrupted
[3]: worker.current_func is found to be irq_affinity_notify which looks abnormal.
process_one_work(
worker = 0xEC048600 -> (
entry = (next = 0x0, prev = 0xEC5AE968),
hentry = (next = 0x0, pprev = 0xEC5AE968),
current_work = 0xEA2585AC,
current_func = 0xC016FD40,
current_pwq = 0xEC5B2400,
desc_valid = FALSE,
The memory content around 0xEC048600 seems to be corrupted especially for irq_affinity_notify at 0xEC04860C.
NSD:EC0485F8| 5A 5A 5A 5A 0x5A5A5A5A
NSD:EC0485FC| 5A 5A 5A 5A 0x5A5A5A5A
NSD:EC048600| 00 00 00 00 0x0 // <<--
NSD:EC048604| 68 E9 5A EC 0xEC5AE968
NSD:EC048608| AC 85 25 EA 0xEA2585AC
NSD:EC04860C| 40 FD 16 C0 0xC016FD40 \\vmlinux\manage\irq_affinity_notify // <<--
NSD:EC048610| 00 24 5B EC 0xEC5B2400
NSD:EC048614| 00 00 00 00 0x0
NSD:EC048618| 18 86 04 EC 0xEC048618
NSD:EC04861C| 18 86 04 EC 0xEC048618
NSD:EC048620| C0 57 2A EC 0xEC2A57C0
NSD:EC048624| 00 E8 5A EC 0xEC5AE800
NSD:EC048628| E8 E0 04 E9 0xE904E0E8
NSD:EC04862C| F0 E9 5A EC 0xEC5AE9F0
NSD:EC048630| AC 8D FF FF 0xFFFF8DAC
Searching "irq_affinity_notify" key word enables me to the definition of irq_affinity_notify structure.
struct irq_affinity_notify {
unsigned int irq;
struct kref kref;
struct work_struct work;
void (*notify)(struct irq_affinity_notify *, const cpumask_t *mask);
void (*release)(struct kref *ref);
};
By casting 0xEA2585AC as struct work_struct, the following debug information can be deduced which looks very odd.
The struct work_struct.entry.next is corrupted as NULL and work_func_t is registered as irq_affinity_notify().
(struct work_struct *) [-] (struct work_struct*)0xEA2585AC = 0xEA2585AC = __bss_stop+0x2857B9A4 -> (
(atomic_long_t) [D:0xEA2585AC] data = ((int) [D:0xEA2585AC] counter = -329571323 = 0xEC5B2405 = '.[
(struct list_head) [D:0xEA2585B0] entry = (
(struct list_head *) [D:0xEA2585B0] next = 0xE9E9EAB4 = __bss_stop+0x281C1EAC -> (
(struct list_head *) [D:0xE9E9EAB4] next = 0x0 = -> NULL,
(struct list_head *) [D:0xE9E9EAB8] prev = 0x0 = -> NULL),
(struct list_head *) [D:0xEA2585B4] prev = 0xEC5AE820 = -> ((struct list_head *) [D:0xEC5AE820]
(work_func_t) [D:0xEA2585B8] func = 0xC016FD40 = irq_affinity_notify -> )
Looking into the symbol information at 0xEA2585AC address, I can have the following symbols below.
(i.e) irq_affinity_notify, pm_qos_irq_notify, pm_qos_irq_release, pm_qos_work_fn
________address|_data________|value_____________|symbol
NSD:EA25859C| FF 00 00 00 0xFF \\vmlinux\Global\up_b_offset+0xCF
NSD:EA2585A0| 9D 00 00 00 0x9D \\vmlinux\Global\up_b_offset+0x6D
NSD:EA2585A4| 9D 00 00 00 0x9D \\vmlinux\Global\up_b_offset+0x6D
NSD:EA2585A8| 03 00 00 00 0x3
NSD:EA2585AC| 05 24 5B EC 0xEC5B2405
NSD:EA2585B0| B4 EA E9 E9 0xE9E9EAB4
NSD:EA2585B4| 20 E8 5A EC 0xEC5AE820
NSD:EA2585B8| 40 FD 16 C0 0xC016FD40 \\vmlinux\manage\irq_affinity_notify
NSD:EA2585BC| 58 90 16 C0 0xC0169058 \\vmlinux\kernel/power/qos\pm_qos_irq_notify
NSD:EA2585C0| 00 90 16 C0 0xC0169000 \\vmlinux\kernel/power/qos\pm_qos_irq_release
NSD:EA2585C4| 00 94 35 77 0x77359400
NSD:EA2585C8| C8 85 25 EA 0xEA2585C8
NSD:EA2585CC| C8 85 25 EA 0xEA2585C8
NSD:EA2585D0| 14 81 86 C1 0xC1868114 \\vmlinux\adreno\device_3d0+0x45C
NSD:EA2585D4| F8 C6 C4 E9 0xE9C4C6F8
NSD:EA2585D8| 01 00 00 00 0x1
NSD:EA2585DC| E0 FF FF FF 0xFFFFFFE0
NSD:EA2585E0| E0 85 25 EA 0xEA2585E0
NSD:EA2585E4| E0 85 25 EA 0xEA2585E0
NSD:EA2585E8| 10 8F 16 C0 0xC0168F10 \\vmlinux\kernel/power/qos\pm_qos_work_fn
NSD:EA2585EC| 00 00 00 00 0x0
NSD:EA2585F0| 00 00 00 00 0x0
NSD:EA2585F4| 00 00 00 00 0x0
NSD:EA2585F8| 02 00 B8 EB 0xEBB80002
NSD:EA2585FC| A8 77 13 C0 0xC01377A8 \\vmlinux\workqueue\delayed_work_timer_fn
NSD:EA258600| DC 85 25 EA 0xEA2585DC
When searching pm_qos_irq_notify in the kernel source code, I can see that pm_qos_irq_notify is registered as req->irq_notify.notify.
void pm_qos_add_request(struct pm_qos_request *req,
int pm_qos_class, s32 value)
{
//snip
case PM_QOS_REQ_AFFINE_IRQ:
if (irq_can_set_affinity(req->irq)) {
int ret = 0;
struct irq_desc *desc = irq_to_desc(req->irq);
struct cpumask *mask = desc->irq_data.affinity;
/* Get the current affinity */
cpumask_copy(&req->cpus_affine, mask);
req->irq_notify.irq = req->irq;
req->irq_notify.notify = pm_qos_irq_notify;
req->irq_notify.release = pm_qos_irq_release;
I can see that pm_qos_irq_notify() as well as pm_qos_irq_release() is registered as struct irq_affinity_notify.
struct irq_affinity_notify {
unsigned int irq;
struct kref kref;
struct work_struct work;
void (*notify)(struct irq_affinity_notify *, const cpumask_t *mask); // pm_qos_irq_notify
void (*release)(struct kref *ref); // pm_qos_irq_release
};
struct pm_qos_request {
enum pm_qos_req_type type;
struct cpumask cpus_affine;
#ifdef CONFIG_SMP
uint32_t irq;
/* Internal structure members */
struct irq_affinity_notify irq_notify;
#endif
struct plist_node node;
int pm_qos_class;
struct delayed_work work; /* for pm_qos_update_request_timeout */
};
The 0xEA2585A4 address is starting point where struct irq_affinity_notify element is located.
(struct irq_affinity_notify *) [-] (struct irq_affinity_notify*)0xEA2585A4
(unsigned int) [D:0xEA2585A4] irq = 157 = 0x9D = '....',
(struct kref) [D:0xEA2585A8] kref = (
(atomic_t) [D:0xEA2585A8] refcount = ((int) [D:0xEA2585A8] counter = 3 = 0x3 = '....')),
(struct work_struct) [D:0xEA2585AC] work = (
(atomic_long_t) [D:0xEA2585AC] data = ((int) [D:0xEA2585AC] counter = -329571323 = 0xEC5B2
(struct list_head) [D:0xEA2585B0] entry = (
(struct list_head *) [D:0xEA2585B0] next = 0xE9E9EAB4
(struct list_head *) [D:0xEA2585B4] prev = 0xEC5AE820
(work_func_t) [D:0xEA2585B8] func = 0xC016FD40 = irq_affinity_notify -> ),
(void (*)()) [D:0xEA2585BC] notify = 0xC0169058 = pm_qos_irq_notify -> ,
(void (*)()) [D:0xEA2585C0] release = 0xC0169000 = pm_qos_irq_release -> )
________address|_data________|value_____________|symbol
NSD:EA25859C| FF 00 00 00 0xFF \\vmlinux\Global\up_b_offset+0xCF
NSD:EA2585A0| 9D 00 00 00 0x9D \\vmlinux\Global\up_b_offset+0x6D
NSD:EA2585A4| 9D 00 00 00 0x9D //struct irq_affinity_notify.irq
NSD:EA2585A8| 03 00 00 00 0x3 //struct irq_affinity_notify.kref
NSD:EA2585AC| 05 24 5B EC 0xEC5B2405 //struct irq_affinity_notify.work.data
NSD:EA2585B0| B4 EA E9 E9 0xE9E9EAB4 //struct irq_affinity_notify.work.entry.next
NSD:EA2585B4| 20 E8 5A EC 0xEC5AE820 //struct irq_affinity_notify.work.entry.prev
NSD:EA2585B8| 40 FD 16 C0 0xC016FD40 \\vmlinux\manage\irq_affinity_notify //struct irq_affinity_notify.work.func
NSD:EA2585BC| 58 90 16 C0 0xC0169058 \\vmlinux\kernel/power/qos\pm_qos_irq_notify
NSD:EA2585C0| 00 90 16 C0 0xC0169000 \\vmlinux\kernel/power/qos\pm_qos_irq_release
NSD:EA2585C4| 00 94 35 77 0x77359400
NSD:EA2585C8| C8 85 25 EA 0xEA2585C8
NSD:EA2585CC| C8 85 25 EA 0xEA2585C8
NSD:EA2585D0| 14 81 86 C1 0xC1868114 \\vmlinux\adreno\device_3d0+0x45C
NSD:EA2585D4| F8 C6 C4 E9 0xE9C4C6F8
NSD:EA2585D8| 01 00 00 00 0x1
NSD:EA2585DC| E0 FF FF FF 0xFFFFFFE0
NSD:EA2585E0| E0 85 25 EA 0xEA2585E0
NSD:EA2585E4| E0 85 25 EA 0xEA2585E0
NSD:EA2585E8| 10 8F 16 C0 0xC0168F10 \\vmlinux\kernel/power/qos\pm_qos_work_fn
NSD:EA2585EC| 00 00 00 00 0x0
NSD:EA2585F0| 00 00 00 00 0x0
NSD:EA2585F4| 00 00 00 00 0x0
NSD:EA2585F8| 02 00 B8 EB 0xEBB80002
NSD:EA2585FC| A8 77 13 C0 0xC01377A8 \\vmlinux\workqueue\delayed_work_timer_fn
NSD:EA258600| DC 85 25 EA 0xEA2585DC
155: 1608 0 0 0 0 0 0 0 GIC mmc0
157: 98 0 0 0 0 0 0 0 GIC mmc1
166: 10 0 0 0 0 0 0 0 GIC msm_otg,msm_hsusb
Taking a looking at the structure associated with struct irq_affinity_notify,
struct pm_qos_request seems to include struct irq_affinity_notify irq_notify.
struct pm_qos_request {
enum pm_qos_req_type type;
struct cpumask cpus_affine;
#ifdef CONFIG_SMP
uint32_t irq;
/* Internal structure members */
struct irq_affinity_notify irq_notify;
#endif
struct plist_node node;
int pm_qos_class;
struct delayed_work work; /* for pm_qos_update_request_timeout */
};
By casting 0xEA258598 as struct pm_qos_request, the whole picture is drawn as below.
(i.e) type = PM_QOS_REQ_AFFINE_IRQ
(struct pm_qos_request *) [-] (struct pm_qos_request*)0xEA258598 = 0xEA258598 = __bss_sto
(enum pm_qos_req_type) [D:0xEA258598] type = PM_QOS_REQ_AFFINE_IRQ = 2 = 0x2 = '....',
(struct cpumask) [D:0xEA25859C] cpus_affine = (
(long unsigned int [1]) [D:0xEA25859C] bits = (
[0] = 255 = 0xFF = '....')),
(uint32_t) [D:0xEA2585A0] irq = 157 = 0x9D = '....',
(struct irq_affinity_notify) [D:0xEA2585A4] irq_notify = ((unsigned int) [D:0xEA2585A4]
(struct plist_node) [D:0xEA2585C4] node = ((int) [D:0xEA2585C4] prio = 2000000000 = 0x7
(int) [D:0xEA2585D8] pm_qos_class = 1 = 0x1 = '....',
(struct delayed_work) [D:0xEA2585DC] work = (
(struct work_struct) [D:0xEA2585DC] work = (
(atomic_long_t) [D:0xEA2585DC] data = ((int) [D:0xEA2585DC] counter = -32 = 0xFFFFF
(struct list_head) [D:0xEA2585E0] entry = ((struct list_head *) [D:0xEA2585E0] next
(work_func_t) [D:0xEA2585E8] func = 0xC0168F10 = pm_qos_work_fn -> ),
(struct timer_list) [D:0xEA2585EC] timer = ((struct list_head) [D:0xEA2585EC] entry =
(struct workqueue_struct *) [D:0xEA258620] wq = 0x0 = -> NULL,
(int) [D:0xEA258624] cpu = 0 = 0x0 = '....'))
(where)
________address|_data________|value_____________|symbol
NSD:EA258590| 00 00 00 00 0x0
NSD:EA258594| 01 00 00 00 0x1
NSD:EA258598| 02 00 00 00 0x2 //enum pm_qos_req_type type;
NSD:EA25859C| FF 00 00 00 0xFF //struct cpumask cpus_affine;
NSD:EA2585A0| 9D 00 00 00 0x9D //uint32_t irq;
NSD:EA2585A4| 9D 00 00 00 0x9D //struct irq_affinity_notify
NSD:EA2585A8| 03 00 00 00 0x3
NSD:EA2585AC| 05 24 5B EC 0xEC5B2405
NSD:EA2585B0| B4 EA E9 E9 0xE9E9EAB4
NSD:EA2585B4| 20 E8 5A EC 0xEC5AE820
NSD:EA2585B8| 40 FD 16 C0 0xC016FD40 \\vmlinux\manage\irq_affinity_notify
NSD:EA2585BC| 58 90 16 C0 0xC0169058 \\vmlinux\kernel/power/qos\pm_qos_irq_notify
NSD:EA2585C0| 00 90 16 C0 0xC0169000 \\vmlinux\kernel/power/qos\pm_qos_irq_release
NSD:EA2585C4| 00 94 35 77 0x77359400
NSD:EA2585C8| C8 85 25 EA 0xEA2585C8
NSD:EA2585CC| C8 85 25 EA 0xEA2585C8
NSD:EA2585D0| 14 81 86 C1 0xC1868114 \\vmlinux\adreno\device_3d0+0x45C
NSD:EA2585D4| F8 C6 C4 E9 0xE9C4C6F8
NSD:EA2585D8| 01 00 00 00 0x1
NSD:EA2585DC| E0 FF FF FF 0xFFFFFFE0
NSD:EA2585E0| E0 85 25 EA 0xEA2585E0
NSD:EA2585E4| E0 85 25 EA 0xEA2585E0
NSD:EA2585E8| 10 8F 16 C0 0xC0168F10 \\vmlinux\kernel/power/qos\pm_qos_work_fn
NSD:EA2585EC| 00 00 00 00 0x0
The (*(((struct pm_qos_request*)0xEA258598))).work.work.data is equal to 0xFFFFFFE0.
[-] (struct pm_qos_request*)0xEA258598 = 0xEA258598 -> (
//snip
D:0xEA2585DC] work = (
[D:0xEA2585DC] work = (
[D:0xEA2585DC] data = ([D:0xEA2585DC] counter = 0xFFFFFFE0), // <<-- WORK_STRUCT_NO_POOL
[D:0xEA2585E0] entry = ([D:0xEA2585E0] next = 0xEA2585E0, [D:0xEA2585E4] prev = 0xEA2585E0),
[D:0xEA2585E8] func = 0xC0168F10),
[D:0xEA2585EC] timer = ([D:0xEA2585EC] entry = ([D:0xEA2585EC] next = 0x0, [D:0xEA2585F0] prev = 0x0), [
[D:0xEA258620] wq = 0x0,
[D:0xEA258624] cpu = 0x0))
So it is needed to apply the following patch to see if the same crash occurs since 0xFFFFFFE0,
where 0xFFFFFFE0 = WORK_STRUCT_NO_POOL = (unsigned long)WORK_OFFQ_POOL_NONE << WORK_OFFQ_POOL_SHIFT,
diff --git a/kernel/power/qos.c b/kernel/power/qos.c
index 5f4c006..a122891 100644
--- a/kernel/power/qos.c
+++ b/kernel/power/qos.c
@@ -405,6 +405,9 @@ void pm_qos_update_request(struct pm_qos_request *req,
return;
}
+ if (work_is_canceling(&req->work) )
+ return;
+
cancel_delayed_work_sync(&req->work);
__pm_qos_update_request(req, new_value);
}
@@ -427,6 +430,9 @@ void pm_qos_update_request_timeout(struct pm_qos_request *req, s32 new_value,
"%s called for unknown object.", __func__))
return;
+ if (work_is_canceling(&req->work) )
+ return;
+
cancel_delayed_work_sync(&req->work);
trace_pm_qos_update_request_timeout(req->pm_qos_class,
@@ -458,6 +464,9 @@ void pm_qos_remove_request(struct pm_qos_request *req)
return;
}
+ if (work_is_canceling(&req->work) )
+ return;
+
cancel_delayed_work_sync(&req->work);
trace_pm_qos_remove_request(req->pm_qos_class, PM_QOS_DEFAULT_VALUE);
static bool work_is_canceling(struct work_struct *work)
{
unsigned long data = atomic_long_read(&work->data);
return !(data & WORK_STRUCT_PWQ) && (data & WORK_OFFQ_CANCELING);
}
(where)
WORK_STRUCT_PWQ = 0x4, WORK_OFFQ_CANCELING = 0x10
In-depth Analysis
The work->data is set as WORK_STRUCT_NO_POOL inside clear_work_data() which is called from
static void clear_work_data(struct work_struct *work)
{
smp_wmb(); /* see set_work_pool_and_clear_pending() */
set_work_data(work, WORK_STRUCT_NO_POOL, 0);
}
static bool __cancel_work_timer(struct work_struct *work, bool is_dwork)
{
static DECLARE_WAIT_QUEUE_HEAD(cancel_waitq);
unsigned long flags;
int ret;
do {
ret = try_to_grab_pending(work, is_dwork, &flags);
if (unlikely(ret == -ENOENT)) {
struct cwt_wait cwait;
init_wait(&cwait.wait);
cwait.wait.func = cwt_wakefn;
cwait.work = work;
prepare_to_wait_exclusive(&cancel_waitq, &cwait.wait,
TASK_UNINTERRUPTIBLE);
if (work_is_canceling(work))
schedule();
finish_wait(&cancel_waitq, &cwait.wait);
}
} while (unlikely(ret < 0));
/* tell other tasks trying to grab @work to back off */
mark_work_canceling(work);
local_irq_restore(flags);
flush_work(work);
clear_work_data(work); // <<--
'Kernel Crash Case-Studies' 카테고리의 다른 글
| [KernelCrash] panic due to voltage droop in the specific device (0) | 2019.03.09 |
|---|---|
| [KernelCrash] Abort at do_raw_spin_lock() with "cat /d/shrinker" (0) | 2019.03.09 |
| [KernelCrash] Abort at tty_wakeup() due to port_tty(null) (0) | 2019.03.09 |
| [KernelCrash] Abort at 0xecb29f00(defective device) (0) | 2019.03.09 |
| [KernelCrash] Abort at mmc_wait_data_done() due to race (0) | 2019.03.09 |