kernel-packages team mailing list archive

[Rafael David Tinoco <rafael.tinoco@xxxxxxxxxxxxx>]

Disconsider my previous analysis please. After disassembling carefully the java
process dump I could see that we had the instruction pointer at:

    if (iter.task)
        put_task_struct(iter.task);

Some instructions before a loop that could be a potential candidate for deadlocks, which
I was referring to before.

   0xffffffff811df242 <+34>:    je     0xffffffff811df24f <next_tgid+47>
   0xffffffff811df244 <+36>:    lock decl 0x10(%rdx)
   0xffffffff811df248 <+40>:    sete   %al
   0xffffffff811df24b <+43>:    test   %al,%al

The combination of those 3 instructions (decl, sete & test) shows me that this is
actually the implementation of atomic_dec_and_test function. It servers to atomically
(CPU coordination) decrement a variable from task_struct for the given task.

Deadlock is probably NOT there.

I went for khungtask stack to check which task it was complaining about being locked
and I could not find it (probably taskid was in registers and not on the stack) BUT
I could find an output message telling me which task was locked:

[15956.371298] INFO: task jsvc:57263 blocked for more than 120 seconds.

And this comes exactly from khungtaskd code. It means that PID 57263 was NOT
scheduled for more than 120 seconds. Checking its stack:

    PID: 57263
COMMAND: "jsvc"
   TASK: ffff883e0c4e2e00  [THREAD_INFO: ffff883e849c2000]
    CPU: 1
  STATE: TASK_UNINTERRUPTIBLE|TASK_TRACED|EXIT_DEAD

I can see that it is in UNINTERRUPTIBLE state (it can't received signals, for ex).
Checking its stack:

crash> bt
PID: 57263  TASK: ffff883e0c4e2e00  CPU: 1   COMMAND: "jsvc"
 #0 [ffff883e849c3c88] __schedule at ffffffff8166256a
 #1 [ffff883e849c3d10] schedule at ffffffff81662c0f
 #2 [ffff883e849c3d20] schedule_timeout at ffffffff8166324d
 #3 [ffff883e849c3dd0] wait_for_common at ffffffff81662a4f
 #4 [ffff883e849c3e70] wait_for_completion at ffffffff81662bcd
 #5 [ffff883e849c3e80] flush_work at ffffffff8108757e
 #6 [ffff883e849c3ed0] schedule_on_each_cpu at ffffffff81087813
 #7 [ffff883e849c3f10] lru_add_drain_all at ffffffff81127365
 #8 [ffff883e849c3f20] sys_fadvise64_64 at ffffffff8111e189
 #9 [ffff883e849c3f70] sys_fadvise64 at ffffffff8111e27e
#10 [ffff883e849c3f80] system_call_fastpath at ffffffff8166d2c2

## sys_fadvise64_64

The task entered kernel mode after the syscall: fadvise. It basically tells the kernel
how the file is going to be accessed so it can prepare itself regarding to different
caching techniques (expect page references in random order, expect page references
in sequential order, expect delay in accessing file contents, etc).

It turns out that the JSVC process basically told kernel that it would NOT use the
opened file (flag POSIX_FADV_DONTNEED) until further moment, at a certain offset. With
that, kernel calculated page start/end index (offset, offset+len) for the memory range
of given file and tried to invalidate all unlocked pages (page cache) for that area.
Dirty, locked, write-back or mapped pages are NOT invalidated.

After first attempt of invalidating pages from page-cache from that particular file,
Kernel found out that fewer pages (than the ones given to fadvise - in the form of
offset/len delta) than expected were invalidated (in other words, it could not invalidate
all pages from the the range) so it resolved calling the LRU DRAIN logic.

## lru_add_drain_all

LRU stands for Least-Recent-Used algorithm and is used for user mode address space and
for page cache (this case). It defines 2 lists of memory pages: active and inactive. The
LRU DRAIN logic schedules a drain logic on every CPU on the system in order to drain
per-cpu existent page vectors (pagevecs).

Page vecs are temporary small & finite data structures containing page descriptor pointers.
Instead of changing LRU lists (active/inactive) directly, the LRU algorithm uses per-cpu
page vectors until they are full (avoiding having to lock/unlock while LRU lists more often).

## schedule_on_each_cpu

Task ffff883e0c4e2e00 continued the LRU DRAIN logic by scheduling its call back function using
schedule_on_each_cpu:

schedule_on_each_cpu(drain_cpu_pagevecs) scheduled the drain_cpu_pagevecs on all cpus
and kept waiting - for more than 120 seconds - for all cpus to execute the drain.

While it was waiting, the task ffff883e0c4e2e00 was made UNINTERRUPTIBLE and was locked
inside this loop where it waits for drain_cpu_pagevecs to finish on all cpus (it never did).

## precise commit (cherry-picked from upstream) adding that logic:

commit a68692ea42825466b0ade8a94a98afc924d2564e
Author: Mel Gorman <mgorman@xxxxxxx>
Date:   Fri Feb 22 16:35:59 2013 -0800

    mm/fadvise.c: drain all pagevecs if POSIX_FADV_DONTNEED fails to
discard all pages

    BugLink: http://bugs.launchpad.net/bugs/1150557

    commit 67d46b296a1ba1477c0df8ff3bc5e0167a0b0732 upstream.

It was added to Precise (3.2.0-40.64).

I'm removing that logic and providing a kernel without it to see if it
mitigates the issue.

Per original commit description, this was supposed to fix an erratic behaviour seen in
s390x architecture for the sys_fadvise64_64 system call. I'm afraid it introduced a race
condition that might have disappeared because of code refactoring in further commits.
If not I'll check if the logic is still plausible for upstream and discuss it appropriately.

I'll provide a hotfixed kernel which I would like to get feedback about.

Thank you

Rafael

-- 
You received this bug notification because you are a member of Kernel
Packages, which is subscribed to linux in Ubuntu.
https://bugs.launchpad.net/bugs/1534413

Title:
  Precise: lockup during fadvise syscall with POSIX_FADV_DONTNEED

Status in linux package in Ubuntu:
  In Progress

Bug description:
  It was brought to my knowledge a kernel dump (3.2.0-79) with the
  following stack trace:

  """
  [14277.952072] usb 3-1: USB disconnect, device number 3
  [15388.602790] NOHZ: local_softirq_pending 02
  [15404.593795] NOHZ: local_softirq_pending 02
  [15436.575787] NOHZ: local_softirq_pending 02
  [15452.566802] NOHZ: local_softirq_pending 02
  [15456.564528] NOHZ: local_softirq_pending 02
  [15564.503842] NOHZ: local_softirq_pending 02
  [15584.492538] NOHZ: local_softirq_pending 02
  [15588.490302] NOHZ: local_softirq_pending 02
  [15632.465563] NOHZ: local_softirq_pending 02
  [15659.014629] NOHZ: local_softirq_pending 02
  [15956.371298] INFO: task jsvc:57263 blocked for more than 120 seconds.
  [15956.375347] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
  [15956.383487] jsvc            D ffffffff81806200     0 57263   9495 0x00000000
  [15956.383493]  ffff883e849c3d08 0000000000000082 ffff883e849c3ca8 000000008104f624
  [15956.383502]  ffff883e849c3fd8 ffff883e849c3fd8 ffff883e849c3fd8 0000000000012800
  [15956.383509]  ffff881f72db9700 ffff883e0c4e2e00 ffff883e849c3cf8 7fffffffffffffff
  [15956.383518] Call Trace:
  [15956.383534]  [<ffffffff81662c0f>] schedule+0x3f/0x60
  [15956.383539]  [<ffffffff8166324d>] schedule_timeout+0x29d/0x310
  [15956.383547]  [<ffffffff810388be>] ? physflat_send_IPI_mask+0xe/0x10
  [15956.383554]  [<ffffffff81032068>] ? native_smp_send_reschedule+0x48/0x60
  [15956.383560]  [<ffffffff8103ec29>] ? default_spin_lock_flags+0x9/0x10
  [15956.383564]  [<ffffffff81662a4f>] wait_for_common+0xdf/0x180
  [15956.383572]  [<ffffffff81060ac0>] ? try_to_wake_up+0x200/0x200
  [15956.383576]  [<ffffffff81662bcd>] wait_for_completion+0x1d/0x20
  [15956.383585]  [<ffffffff8108757e>] flush_work+0x2e/0x40
  [15956.383589]  [<ffffffff810838b0>] ? wake_up_worker+0x30/0x30
  [15956.383593]  [<ffffffff81087813>] schedule_on_each_cpu+0xc3/0x110
  [15956.383602]  [<ffffffff81127365>] lru_add_drain_all+0x15/0x20
  [15956.383607]  [<ffffffff8111e189>] sys_fadvise64_64+0x189/0x270
  [15956.383610]  [<ffffffff8111e27e>] sys_fadvise64+0xe/0x10
  [15956.383619]  [<ffffffff8166d2c2>] system_call_fastpath+0x16/0x1b
  [15956.383622] Kernel panic - not syncing: hung_task: blocked tasks
  [15956.388083] Pid: 178, comm: khungtaskd Tainted: G        W    3.2.0-79-generic #115-Ubuntu
  [15956.397273] Call Trace:
  [15956.401783]  [<ffffffff8164c005>] panic+0x91/0x1a4
  [15956.406527]  [<ffffffff810d97c2>] check_hung_task+0xb2/0xc0
  [15956.411393]  [<ffffffff810d98eb>] check_hung_uninterruptible_tasks+0x11b/0x140
  [15956.421117]  [<ffffffff810d9910>] ? check_hung_uninterruptible_tasks+0x140/0x140
  [15956.431847]  [<ffffffff810d995f>] watchdog+0x4f/0x60
  [15956.437524]  [<ffffffff8108b99c>] kthread+0x8c/0xa0
  [15956.443145]  [<ffffffff8166f434>] kernel_thread_helper+0x4/0x10
  [15956.448830]  [<ffffffff8108b910>] ? flush_kthread_worker+0xa0/0xa0
  [15956.454700]  [<ffffffff8166f430>] ? gs_change+0x13/0x13
  """

  Analysis being made on the comments...

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1534413/+subscriptions