lkml.org 
[lkml]   [2011]   [Dec]   [1]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: [3.2-rc3] OOM killer doesn't kill the obvious memory hog
    On Fri, Dec 02, 2011 at 12:59:21PM +1100, Dave Chinner wrote:
    > On Thu, Dec 01, 2011 at 02:35:31PM -0800, David Rientjes wrote:
    > > On Thu, 1 Dec 2011, Dave Chinner wrote:
    > >
    > > > > /*
    > > > > * /proc/<pid>/oom_score_adj set to OOM_SCORE_ADJ_MIN disables oom killing for
    > > > > * pid.
    > > > > */
    > > > > #define OOM_SCORE_ADJ_MIN (-1000)
    > > > >
    > > > >
    > > > > IIUC, this task cannot be killed by oom-killer because of oom_score_adj settings.
    > > >
    > > > It's not me or the test suite that setting this, so it's something
    > > > the kernel must be doing automagically.
    > > >
    > >
    > > The kernel does not set oom_score_adj to ever disable oom killing for a
    > > thread. The only time the kernel touches oom_score_adj is when setting it
    > > to "1000" in ksm and swap to actually prefer a memory allocator for oom
    > > killing.
    > >
    > > It's also possible to change this value via the deprecated
    > > /proc/pid/oom_adj interface until it is removed next year. Check your
    > > dmesg for warnings about using the deprecated oom_adj interface or change
    > > the printk_once() in oom_adjust_write() to a normal printk() to catch it.
    >
    > No warnings at all, as I've already said. If it is userspace,
    > whatever is doing it is using the oom_score_adj interface correctly.

    .....

    > <sigh>
    >
    > The reports all cycle around this loop:
    >
    > linux-mm says userspace/distro problem
    > distro says openssh problem
    > openssh says kernel problem
    >
    > And there doesn't appear to be any resolution in any of the reports,
    > just circular finger pointing and frustrated users.
    >
    > I can't find anything in the distro startup or udev scripts that
    > modify the oom parameters, and the openssh guys say they only
    > pass on the value inhereted from ssh's parent process, so it clearly
    > not obvious where the bug lies at this point. It's been around for
    > some time, though...
    >
    > More digging to do...

    A working sshd startup and login:

    Dec 2 13:16:32 test-2 sshd[2119]: Set /proc/self/oom_score_adj from 0 to -1000
    Dec 2 13:16:32 test-2 sshd[2119]: debug1: Bind to port 22 on 0.0.0.0.
    Dec 2 13:16:32 test-2 sshd[2119]: Server listening on 0.0.0.0 port 22.
    Dec 2 13:16:32 test-2 sshd[2119]: socket: Address family not supported by protocol
    Dec 2 13:16:36 test-2 sshd[2119]: debug1: Forked child 2576.
    Dec 2 13:16:36 test-2 sshd[2576]: Set /proc/self/oom_score_adj to 0

    The child process sets itself back to 0 correctly. Now, a non-working
    startup and login:

    Dec 2 13:19:56 test-2 sshd[2126]: Set /proc/self/oom_score_adj from 0 to -1000
    Dec 2 13:19:56 test-2 sshd[2126]: debug1: Bind to port 22 on 0.0.0.0.
    Dec 2 13:19:56 test-2 sshd[2126]: Server listening on 0.0.0.0 port 22.
    Dec 2 13:19:56 test-2 sshd[2126]: socket: Address family not supported by protocol
    Dec 2 13:19:57 test-2 sshd[2126]: Received signal 15; terminating.
    Dec 2 13:19:57 test-2 sshd[2317]: Set /proc/self/oom_score_adj from -1000 to -1000
    Dec 2 13:19:57 test-2 sshd[2317]: debug1: Bind to port 22 on 0.0.0.0.
    Dec 2 13:19:57 test-2 sshd[2317]: Server listening on 0.0.0.0 port 22.
    Dec 2 13:19:57 test-2 sshd[2317]: socket: Address family not supported by protocol
    Dec 2 13:20:01 test-2 sshd[2317]: debug1: Forked child 2322.
    Dec 2 13:20:01 test-2 sshd[2322]: Set /proc/self/oom_score_adj to -1000

    Somewhere in the statup process, a sshd process is getting a SIGTERM
    and dying. It is then restarted immediately form a context that has
    a /proc/self/oom_score_adj value of -1000, which is where the
    problem lies. So, how does this occur? Looks like a distro problem -
    I added 'echo "sshd restart" >> /var/log/auth.log' to the
    /etc/init.d/ssh restart command, and this pops out now:

    Dec 2 14:00:08 test-2 sshd[2037]: debug3: oom_adjust_setup
    Dec 2 14:00:08 test-2 sshd[2037]: Set /proc/self/oom_score_adj from 0 to -1000
    Dec 2 14:00:08 test-2 sshd[2037]: debug2: fd 3 setting O_NONBLOCK
    Dec 2 14:00:08 test-2 sshd[2037]: debug1: Bind to port 22 on 0.0.0.0.
    Dec 2 14:00:08 test-2 sshd[2037]: Server listening on 0.0.0.0 port 22.
    Dec 2 14:00:08 test-2 sshd[2037]: socket: Address family not supported by protocol
    sshd restart
    Dec 2 14:00:11 test-2 sshd[2037]: Received signal 15; terminating.
    Dec 2 14:00:11 test-2 sshd[2330]: debug3: oom_adjust_setup
    Dec 2 14:00:11 test-2 sshd[2330]: Set /proc/self/oom_score_adj from -1000 to -1000

    So, something in a startup script is causing an sshd restart from a
    context where the oom_score_adj = -1000. There's only two
    possibilities here - the dhcp client bringing the network interface
    up or a udev event after the sshd has been started.

    Bingo:

    $ sudo ifup --verbose eth0
    Configuring interface eth0=eth0 (inet)
    run-parts --verbose /etc/network/if-pre-up.d
    run-parts: executing /etc/network/if-pre-up.d/bridge
    run-parts: executing /etc/network/if-pre-up.d/uml-utilities

    dhclient -v -pf /var/run/dhclient.eth0.pid -lf
    /var/lib/dhcp/dhclient.eth0.leases eth0
    Internet Systems Consortium DHCP Client 4.1.1-P1
    Copyright 2004-2010 Internet Systems Consortium.
    All rights reserved.
    For info, please visit https://www.isc.org/software/dhcp/

    Listening on LPF/eth0/00:e4:b6:63:63:6e
    Sending on LPF/eth0/00:e4:b6:63:63:6e
    Sending on Socket/fallback
    DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 6
    DHCPOFFER from 192.168.1.254
    DHCPREQUEST on eth0 to 255.255.255.255 port 67
    DHCPACK from 192.168.1.254
    bound to 192.168.1.61 -- renewal in 17198 seconds.
    run-parts --verbose /etc/network/if-up.d
    run-parts: executing /etc/network/if-up.d/mountnfs
    run-parts: executing /etc/network/if-up.d/ntpdate
    run-parts: executing /etc/network/if-up.d/openssh-server
    run-parts: executing /etc/network/if-up.d/uml-utilities
    $

    and /etc/network/if-up.d/openssh-server does a restart on the
    ssh server.

    And this is set in /etc/network/interfaces:

    allow-hotplug eth0

    which means udev can execute the ifup command whenteh device
    appears, asynchronously to the startup scripts that are running.

    So, it's a distro bug - sshd should never be started from from udev
    context because of this inherited oom_score_adj thing.
    Interestingly, the ifup ssh restart script says this:

    # We'd like to use 'reload' here, but it has some problems; see #502444.
    if [ -x /usr/sbin/invoke-rc.d ]; then
    invoke-rc.d ssh restart >/dev/null 2>&1 || true
    else
    /etc/init.d/ssh restart >/dev/null 2>&1 || true
    fi

    Bug 502444 describes the exact startup race condition that I've just
    found. It does a ssh server restart because reload causes the sshd
    server to fail to start if a start is currently in progress. So,
    rather than solving the start vs reload race condition, it got a
    bandaid (use restart to restart sshd from the reload context) and
    left it as a landmine.....

    <sigh>

    Cheers,

    Dave.

    --
    Dave Chinner
    david@fromorbit.com


    \
     
     \ /
      Last update: 2011-12-02 04:35    [W:0.035 / U:178.312 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site