cpu hung at insmod

Question

I am trying to write a block device driver in such a way that the I/O request is handed over to a separate worker thread. The worker thread waits to get a request and then performs the actual I/O.

I am using complete structure for synchronization between the worker thread and the transfer request function. The worker thread does wait_for_completion before proceeding with the request and is woken up when the transfer request gets a request.

However my system hangs right when I try to do insmod. This is how the backtrace looks on each CPU

[  152.036031] BUG: soft lockup - CPU#0 stuck for 22s! [mount:1752]
[  152.036046] CPU 0
[  152.036046] Call Trace:
[  152.036046]  [<ffffffff8108d3e3>] smp_call_function+0x33/0x60
[  152.036046]  [<ffffffff8108d443>] on_each_cpu+0x33/0xa0
[  152.036046]  [<ffffffff81189e95>] __blkdev_put+0x185/0x1f0
[  152.036046]  [<ffffffff8115570a>] __fput+0xaa/0x200
[  152.036046]  [<ffffffff81151f3f>] filp_close+0x5f/0x90
[  152.036046]  [<ffffffff8115201d>] sys_close+0xad/0x120
[  152.036046]  [<ffffffff815a7312>] system_call_fastpath+0x16/0x1b

[  158.233026] INFO: rcu_preempt_state detected stalls on CPUs/tasks: { 2} (detected by 0, t=60002 jiffies)
[  158.233031] sending NMI to all CPUs:

[  158.233031] NMI backtrace for cpu 0
[  158.233031] CPU 0 
[  158.233031] Call Trace:
[  158.233031]  [<ffffffff8102018f>] arch_trigger_all_cpu_backtrace+0x4f/0x90
[  158.233031]  [<ffffffff810ca429>] print_other_cpu_stall+0x159/0x1c0
[  158.233031]  [<ffffffff810cb5e1>] __rcu_pending+0x31/0x180
[  158.233031]  [<ffffffff810cbb4a>] rcu_check_callbacks+0x11a/0x190
[  158.233031]  [<ffffffff8106505f>] update_process_times+0x3f/0x80
[  158.233031]  [<ffffffff8108772b>] tick_sched_timer+0x5b/0xc0
[  158.233031]  [<ffffffff8107a2ce>] __run_hrtimer+0x6e/0x240
[  158.233031]  [<ffffffff8107acf5>] hrtimer_interrupt+0xe5/0x200
[  158.233031]  [<ffffffff8101efb3>] smp_apic_timer_interrupt+0x63/0xa0
[  158.233031]  [<ffffffff815a7e5e>] apic_timer_interrupt+0x6e/0x80
[  158.233031]  [<ffffffff8108d30e>] smp_call_function_many+0x1fe/0x2a0
[  158.233031]  [<ffffffff8108d3e3>] smp_call_function+0x33/0x60
[  158.233031]  [<ffffffff8108d443>] on_each_cpu+0x33/0xa0
[  158.233031]  [<ffffffff81189e95>] __blkdev_put+0x185/0x1f0
[  158.233031]  [<ffffffff8115570a>] __fput+0xaa/0x200
[  158.233031]  [<ffffffff81151f3f>] filp_close+0x5f/0x90
[  158.233031]  [<ffffffff8115201d>] sys_close+0xad/0x120
[  158.233031]  [<ffffffff815a7312>] system_call_fastpath+0x16/0x1b

[  158.233291] CPU 3 and CPU 1
[  158.233347] Call Trace:
[  158.233352]  [<ffffffff8101eb68>] lapic_next_event+0x18/0x20
[  158.233356]  [<ffffffff81087288>] tick_dev_program_event+0x38/0x100
[  158.233360]  [<ffffffff8107ad2d>] hrtimer_interrupt+0x11d/0x200
[  158.233363]  [<ffffffff8101efb3>] smp_apic_timer_interrupt+0x63/0xa0
[  158.233366]  [<ffffffff815a7e5e>] apic_timer_interrupt+0x6e/0x80
[  158.233371]  [<ffffffff81029aa2>] native_safe_halt+0x2/0x10
[  158.233374]  [<ffffffff8100a67d>] default_idle+0x4d/0x2a0
[  158.233378]  [<ffffffff810011a6>] cpu_idle+0x86/0xd0

[  137.645911] CPU 2 
[  137.645911] Call Trace:
[  137.645911]  [<ffffffff8159d766>] wait_for_common+0x26/0x150
[  137.645911]  [<ffffffffa01674e2>] tsdd_worker_thread+0x72/0x1b0 [tsdd]
[  137.645911]  [<ffffffff81075eee>] kthread+0x7e/0x90
[  137.645911]  [<ffffffff815a94f4>] kernel_thread_helper+0x4/0x10`

... and eventually system hangs.

I vaguely understand what seems to be happening here. The (tsdd) worker thread is running on CPU 2, waiting on wait_for_completion(). On CPU0 there is a close system call. It seems to wait for a response from all other CPUs. It gets responses from all except CPU2. it's waiting too long (BUG: soft lockup - CPU#0 stuck for 22s!) and there is a timer interrupt.

Now this interrupt is broadcast to all CPUs. The wait_for_completion() function makes the thread on CPU2 wait until completion_done. It will not wake the thread even in case of an interrupt. When there is a timer interrupt as in this case, the interrupt is being sent to all the CPUs including CPU2 where our thread is stuck at wait_for_completion(). It will not be able to service the interrupt and system eventually hung.

Is this observation correct, or is there something more going on?

Below is a brief pseudocode:

static struct request *sch_req = NULL;  //global
static struct complete *comp = NULL;    // initialized in module_init

void transfer_req(req_queue) {
    req = blk_fetch_request(req_queue);
    served = 0;
    while (!served) {
        if (completion_done(comp))
            continue;
        sch_req = req;
        sch_queue = req_queue;
        complete(comp);
        served = 1;
    }
}

void worker_thread() {
    while (!kthread_should_stop()) {
        if (wait_for_completion(comp))
            continue;
        while (sch_req) {
            perform_IO(sch_req);
            sch_req = blk_fetch_req(sch_queue);
        }
        init_completion(comp);
    }
}

Can someone help to figure what is wrong here? I would also like to get some insights on how to fix the issue. I even tried using wait_for_completion_interruptible, but that does not seem to solve the problem.

Thanks

P.S. - sorry for the long post (there is no way to attach log files)

Answer 1

Looks like CPU0 is stuck waiting for CSD locks. Did you check for missing IPI interrupts between the CPUs?