Memory Allocated for Included Tasks is Never Recovered #31673

mrstevek · 2017-10-12T23:32:22Z

ISSUE TYPE

Bug Report

COMPONENT NAME

include (but probably any task as well)

ANSIBLE VERSION

ansible 2.4.0.0
  config file = /root/workspace/ansible-memory-leak/ansible.cfg
  configured module search path = [u'/root/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /root/workspace/ansible-2.4.0.0/lib/ansible
  executable location = /root/workspace/ansible-2.4.0.0/bin/ansible
  python version = 2.7.5 (default, Aug  2 2016, 04:20:16) [GCC 4.8.5 20150623 (Red Hat 4.8.5-4)]

CONFIGURATION

For this test playbook, added the following to ansible.cfg:

callback_whitelist = profile_memory

OS / ENVIRONMENT

Control host: Red Hat Enterprise Linux Server release 7.3 (Maipo)
Targets: NA

SUMMARY

On the control machine, Ansible process memory increases with the number of tasks in the playbook. The most noticeable jumps are when an include task is processed and several tasks are read in. The problem is that the memory is never released. For our production playbook, if the server does not have enough memory, Ansible crashes with this error:

ERROR! Unexpected Exception: [Errno 12] Cannot allocate memory.

In our production playbook, each include task increases the memory by about 100MB.

STEPS TO REPRODUCE

Install the memory profiler:

pip install -U memory_profiler

update ansible.cfg with this line:

callback_whitelist = profile_memory

Run the playbook:

ansible-playbook memory_leak.yml

memory_leak.yml

---

- name: Demonstrate memory growth as tasks are included
  hosts: localhost
  gather_facts: false


  tasks:

  - include: foo/some_tasks.yml
    with_sequence: start=1 end=10

  - include: foo/some_tasks.yml
    with_sequence: start=1 end=10

  - include: foo/some_tasks.yml
    with_sequence: start=1 end=10

...

foo/some_tasks.yml

---

- name: Get timestamp
  set_fact:
    timestamp: "{{ lookup('pipe', 'date +%s.%3N') }}"
  delegate_to: localhost
  register: task_result

- debug:
    var: task_result

...

callback_plugins/profile_memory.py

from ansible.plugins.callback import CallbackBase
from ansible import constants as C
from memory_profiler import profile

class CallbackModule(CallbackBase):
    """
    This callback module tells you how much memory a task takes
    """
    CALLBACK_VERSION = 2.0
    CALLBACK_TYPE = 'aggregate'
    CALLBACK_NAME = 'profile_memory'
    CALLBACK_NEEDS_WHITELIST = True


    def __init__(self):
        super(CallbackModule, self).__init__()

    @profile(precision=3)
    def v2_playbook_on_task_start(self, task, is_conditional):
        self.playbook_on_task_start(task.name, is_conditional)

EXPECTED RESULTS

My expectation is that once the life cycle of a task is complete (task has run and results returned), across all applicable hosts, all memory allocated for that task and supporting objects should be released, such that memory use is mostly flat, instead of ever-increasing, for any number of tasks.

ACTUAL RESULTS


PLAY [Demonstrate memory growth as tasks are included] ************************************************************************************************************************************************************

TASK [include] ****************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   47.641 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   47.641 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   48.691 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   48.691 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   48.781 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   48.781 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850676.742"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   48.895 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   48.895 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   48.895 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   48.895 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850676.842"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   48.953 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   48.953 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   48.984 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   48.984 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850676.943"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   48.992 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   48.992 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.023 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.023 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850677.065"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.051 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.051 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.055 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.055 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850677.163"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.148 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.148 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.148 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.148 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850677.271"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.184 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.184 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.199 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.199 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850677.378"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.207 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.207 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.250 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.250 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850677.483"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.262 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.262 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.266 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.266 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850677.623"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.293 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.293 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.293 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.293 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850677.733"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [include] ****************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   49.293 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   49.293 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.094 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.094 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.148 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.148 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.014"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.152 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.152 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.184 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.184 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.126"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.277 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.277 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.277 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.277 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.248"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.301 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.301 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.316 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.316 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.349"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.320 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.320 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.355 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.355 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.450"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.367 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.367 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.371 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.371 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.549"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.395 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.395 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.395 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.395 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.649"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.422 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.422 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.453 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.453 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.768"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.465 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.465 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.484 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.484 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.875"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.508 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.508 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.520 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.520 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850678.997"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [include] ****************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   50.531 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   50.531 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost
included: /root/workspace/ansible-memory-leak/foo/some_tasks.yml for localhost

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.020 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.020 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.031 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.031 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850679.480"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.109 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.109 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.125 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.125 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850679.592"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.152 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.152 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.219 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.219 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850679.714"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.230 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.230 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850679.850"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850679.981"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850680.111"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850680.216"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850680.321"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.234 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.234 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850680.419"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

TASK [Get timestamp] **********************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.262 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.262 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost -> localhost]

TASK [debug] ******************************************************************************************************************************************************************************************************
Filename: /root/workspace/ansible-memory-leak/callback_plugins/profile_memory.py

Line #    Mem usage    Increment   Line Contents
================================================
    20   52.262 MiB    0.000 MiB       @profile(precision=3)
    21                                 def v2_playbook_on_task_start(self, task, is_conditional):
    22   52.262 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1507850680.523"
        }, 
        "ansible_facts_cacheable": false, 
        "changed": false, 
        "failed": false
    }
}

PLAY RECAP ********************************************************************************************************************************************************************************************************
localhost                  : ok=90   changed=0    unreachable=0    failed=0

The text was updated successfully, but these errors were encountered:

rahimkhoja · 2017-10-26T17:43:56Z

We seem to be having Memory Leak issues with 2.4. I will try and get more details.

From what I have been told, on our clients that we upgraded to 2.4, after the memory leak, we downgraded to 2.3.something, and the problem remains.

Apparently we are using lots of includes.

Perhaps the issues is Python? ( Was a thought that my coworker had )

mrstevek · 2017-10-27T23:57:57Z

Besides 2.4, we're seeing the issue in 2.3.1.

alikins · 2017-12-15T17:21:13Z

I can reproduce this sort of with:
ansible 2.5.0 (devel ff923fb) last updated 2017/12/14 15:54:43 (GMT -400)

I put the repro test case info at https://github.com/alikins/ansible-bug-repro/tree/master/mem_usage_a24_31673

Reproducing with f27/python2.7, the memory profile info grew 55MB to 60MB at the last memory profile output. So u

Line #    Mem usage    Increment   Line Contents
================================================
    18   60.086 MiB   60.086 MiB       @profile(precision=3)
    19                                 def v2_playbook_on_task_start(self, task, is_conditional):
    20   60.086 MiB    0.000 MiB           self.playbook_on_task_start(task.name, is_conditional)


ok: [localhost] => {
    "task_result": {
        "ansible_facts": {
            "timestamp": "1513284889.089"
        }, 
        "changed": false, 
        "failed": false
    }

ssuchter · 2018-01-06T08:02:37Z

I've been hit by this same issue. It rendered our main playbook inoperable. (vs running on Ansible 2.1, in which it ran fine). We run this playbook on an admin host that has 4G of RAM, and normally, we're never even vaguely close to any limits, and now the process fails with OOM.

I think it's because we have a lot of tasks that are included in loops. We need them because we set up hundreds of services on dozens of servers. (So I can't use import_tasks, which I suspect doesn't have such a memory problem.)

On a test system with a simpler run of the same playbook (less services and hosts) I validated that Ansible 2.4 is using many times the RAM of Ansible 2.1, I used /usr/bin/time -v on the whole ansible-playbook invocation, which gives a very clear report of the max RAM (RSS) used.

Is there anything I could do to help here? I don't know anything about developing/debugging Ansible internals, so probably not, but if there are any things that I could do to help move this forward/make it easier for it to be debugged/resolved, I'm motivated.

ssuchter · 2018-01-08T05:41:05Z

I did a bunch of test runs against various ansible versions. (Everything that pip would install for me.) It seems like there were two jumps in RSS memory usage, one in 2.2 and one in 2.4:

version run1  run2  run3
2.1.3.0 16396 16268 16404
2.1.4.0 16344 16252 16396
2.1.5.0 16380 16336 16380
2.1.6.0 16380 16376 16192
2.2.0.0 43820 43796 43964
2.2.1.0 45556 46332 45936
2.2.2.0 46012 45856 45820
2.2.3.0 46892 46924 47092
2.3.0.0 47508 47520 47536
2.3.1.0 45492 45568 45608
2.3.2.0 45644 45840 45528
2.3.3.0 45752 45544 45688
2.4.0.0 53748 53904 53888
2.4.1.0 53808 53876 54028
2.4.2.0 54020 53732 53732

I don't think that anyone should read anything into the magnitude of the jumps. It's just when they happened that I imagine is most relevant.

Next stop is looking at commits, seeing if I can narrow down the commit that caused each jump. I imagine that I will "compile" from source to do that.

maxamillion · 2018-01-08T16:07:44Z

Can we test again now that this has been merged? #34461

ssuchter · 2018-01-08T16:23:30Z

Ah, I had hope that this was going to solve the problem, but alas, it seems it did not. I used a clean repo, which means I’m operating off of the ‘devel’ branch. [ec2-user@ip-10-32-2-176 ansible]$ ansible-playbook --version ansible-playbook 2.5.0 (devel 46263d7) last updated 2018/01/08 16:15:23 (GMT +000) config file = None configured module search path = [u'/home/ec2-user/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules'] ansible python module location = /bigdisk/ansible/lib/ansible executable location = /bigdisk/ansible/bin/ansible-playbook python version = 2.7.11 (default, Feb 1 2017, 18:42:03) [GCC 4.1.2 20080704 (Red Hat 4.1.2-54)] [ec2-user@ip-10-32-2-176 ansible_memory_leak]$ /usr/bin/time -v ansible-playbook memory_leak.yml |& grep 'Maximum resident set size' Maximum resident set size (kbytes): 56992 [ec2-user@ip-10-32-2-176 ansible_memory_leak]$ /usr/bin/time -v ansible-playbook memory_leak.yml |& grep 'Maximum resident set size' Maximum resident set size (kbytes): 56656 [ec2-user@ip-10-32-2-176 ansible_memory_leak]$ /usr/bin/time -v ansible-playbook memory_leak.yml |& grep 'Maximum resident set size' Maximum resident set size (kbytes): 56772 This is similar to other the output of the testing against other 2.4 releases. Sean On January 8, 2018 at 8:08:48 AM, Adam Miller (notifications@github.com) wrote: Can we test again now that this has been merged? #34461 <#34461> — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#31673 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AB2E29vbExX4QgEAA2BtSJcrqIOJksygks5tIj2PgaJpZM4P3xfO> .

maxamillion · 2018-01-08T16:33:09Z

@ssuchter thanks for checking

ssuchter · 2018-01-08T16:47:11Z

This is against various branches in a checkout:

branch     run1  run2  run3  run4  run5  median
stable-2.1 35836 29072 29036 29060 28880 29060
stable-2.2 36452 30004 29928 29968 29824 29968
stable-2.3 45608 45548 45632 45656 45412 45608
stable-2.4 54320 53728 54000 53488 53948 53948
devel      57364 57060 56916 56840 57068 57060

ssuchter · 2018-01-08T17:37:27Z

Ok, I definitely don't understand why but I have found one change that significantly increases the RAM footprint of ansible-playbook. The thing that mystifies me is which change it is:

commit 6ba6819
Author: James Cammarata jimi@sngx.net
Date: Thu Dec 8 01:16:08 2016 -0500
Re-adding the init py for modules

Here's my evidence that this commit causes significant memory usage. I checked out various revisions and narrowed down a range until I got to the exact commit that caused memory usage increase. I tried many commits immediately before and immediately after this one, and it was exactly this one that caused a significant change, it seems.

In the below table, rev_idx is how many back from the head (currently 46263d7) the revision is. I used this to narrow down which revisions to look at.

revision   rev_idx median run1  run2  run3  run4  run5  run6  run7  run8  run9  run10 run11 run12
46263d77f1 1       51688  51848 51592 51688 51748 51228 51864 52188 51812 51140 51804 51684 51336
1fd454e5b5 1000    47892  49024 47564 47704 49048 47604 47880 48568 47904 47780
df941df01d 2000    47624  47648 47568 47580 47916 47600 47288 47652 48680 47600
2e85272cd5 4000    47680  47608 47720 47732 47916 47384 47636 47640 47720 47584
0d67a49d5a 5000    50748  50964 50508 50532
6a4324ee99 6000    48992  48928 48956 49028
d1b38cb718 7000    46888  47116 46980 46596 47024 46720 46888
727ca6f436 7200    44904  45056 44752 44684
3fa1ddc9db 7400    44960  44896 44928 44692 45172 44984 44952 45012 44968 45004 45240 44960 44520
345e39e1b1 7401    45036  45108 44752 44964
1da20c9716 7402    44964  45036 44652 44892
ec95cbc96e 7403    44956  45016 44824 44896
71cc868f2b 7404    44308  45208 44800 44928 44308 44096 43796
b9e98406bd 7405    44456  45132 44788 44800 44456 43744 43748
c709b22e5c 7406    44376  44936 44888 44892 44376 43760 43784
1c9a58a885 7407    44416  44912 44896 44680 44416 43840 43788
fa5386c488 7408    44846  44988 44672 45008 45220 44776 44916 43536 43812 43924
6ba6819446 7409    44742  45196 44728 44692 45012 44756 44852 44352 43656 43800
0b47c908eb 7410    26844  27104 26844 26856 26956 26852 26632 27136 26660 26884 26348 25536 25748
250b0dff46 7411    26448  27132 26584 26884 26448 25584 25632
cb1888125d 7412    26348  27052 26660 26584 26348 25752 25644
5628e260f2 7413    25962  26220 25704 25516
573078fc6b 7414    25960  26300 25568 25620
75c281debc 7415    26002  26328 25584 25676
580401c02b 7420    26966  27084 26848 26848
b5a63a556d 7430    26984  27116 26852 26828
d2fc24b771 7440    26874  26864 26884 26856
5bfbeadca3 7450    26648  26936 26648 26636 27148 26860 26648
2f369dff88 7500    26862  26872 26852 26572
7e6fe97f57 7550    26834  26936 26584 26732
1e00adefd5 7600    26688  27108 26660 26584 27144 26872 26688
10ac3ba617 7800    26762  26940 26584 26548
a2f9e0d2fe 8000    26808  26856 26880 26872 26920 26772 26664 26924 26576 26872 26808 26548 26668

There seem to be a couple newer jumps too, I'm going to look for them.

ssuchter · 2018-01-08T17:48:21Z

I found a smaller, but significant jump in memory due to this commit:

commit dd0257b
Author: James Cammarata jimi@sngx.net
Date: Tue Dec 20 08:43:39 2016 -0600

Template "original_task" fields in _process_pending_results

Since we no longer use a post-validated task in _process_pending_results, we
need to be sure to template fields used in original_task as they are raw and
may contain variables.

This patch also moves the handler tracking to be per-uuid, not per-object.
Doing it per-object had implications for the above due to the fact that the
copy of the original task is now being used, so the only sure way is to track
based on the uuid instead.

Fixes #18289

That per-uuid change seems like it could cause memory management changes, that might be something to look at.

Evidence:

revision   rev_idx median run1  run2  run3  run4  run5  run6
d70d279c4e 7190    47026  47164 46664 46800 47124 46800 46928
446888ef41 7191    46760  47056 46756 46760
0d06b77970 7192    46820  46968 46820 46808
dd0257b995 7193    46808  47108 46808 46804
7faa041636 7194    43808  44472 43808 43756
a999452b68 7195    43804  44396 43796 43804
3691c784d2 7196    43780  44416 43744 43780
91094ec96c 7197    43792  44316 43784 43792

ssuchter · 2018-01-08T18:04:49Z

There's another jump (although small) in this commit:

commit 3d65482
Author: James Cammarata jimi@sngx.net
Date: Fri Feb 17 09:14:26 2017 -0600
Stash post-validated fields of the task in the TaskResult

This allows us to have a snapshot of the fields, which we can restore
on the pre-fork side so as to avoid having to re-template fields.

revision   rev_idx median run1  run2  run3  run4  run5  run6
c136ff58c0 6002    47276  47792 47276 47332
bedf0279a9 6003    47264  47568 47700 47264
3d65482927 6004    47352  47612 47216 47352 47596 47276 47352
40235d7b99 6005    45840  45840 46696 47132
a1b3664ec4 6006    46546  46236 46600 46376 47452 46492 47048
879feff6b7 6007    46324  46652 46756 46324
01436cf186 6008    46378  45772 45900 46348 46408 46924 46744

ssuchter · 2018-01-08T18:20:25Z

Another jump (small) in this commit:

commit a108f0f
Author: Brian Coca bcoca@users.noreply.github.com
Date: Mon Apr 24 15:19:52 2017 -0400
avoid hosts 'pre templated warnings' (#23878)

* avoid hosts 'pre templated warnings'

fixed is_template failing on undefined
fixes #23057

* py3 compat

revision   rev_idx median run1  run2  run3  run4  run5  run6
cb13aea88b 5034    48976  49192 48976 49032
d021d8f16b 5035    49016  49228 49016 49088
380ac577c6 5036    49180  49584 48996 48976 49196 49604 49164
a108f0fcd3 5037    49000  49120 49004 49000
74e385e43a 5038    47640  47812 47612 47644 47824 47520 47636
e0a7105c2d 5039    47632  47872 47664 47632
80327d9d47 5040    47718  47836 47644 47792 47844 47624 47612

ssuchter · 2018-01-08T18:32:26Z

Here's a commit that made a small but meaningful RAM improvement (uses less RAM):

commit 78478e8
Author: James Cammarata jimi@sngx.net
Date: Thu May 11 14:57:30 2017 -0500

Avoid default serialization of classes in dump_attrs

For playbook base objects, when dumping attributes via dump_attrs() an
attribute like loop_control is a class. Using the default serialization
for these is slow and consumes a lot of memory. Since LoopControl is also
based on the Base class, we can use serialize() instead and save a lot of
resources.

This also adds a from_attrs() complimentary method to nicely turn the
dumped attrs back into proper field attributes.

Fixes #23579

revision   rev_idx median run1  run2  run3  run4  run5  run6
a47fbba8ae 4804    45616  45584 45784 45736 45648 45472 45408
4638b5f2da 4805    45672  45992 45688 45672
78478e80ea 4806    45672  45656 45388 45384 45836 45812 45688
409fe1a3c3 4807    49168  49336 49168 49496
b04df23da2 4808    49518  49192 49544 49492 49620 49616 49232
c50cf22d52 4809    48824  48824 49540 49416
4a5cf0b5c1 4810    49060  49304 49060 49140

ssuchter · 2018-01-08T18:54:02Z

This commit increases RAM usage somewhat:

commit db749de
Author: Brian Coca brian.coca+git@gmail.com
Date: Sun Oct 29 00:33:02 2017 -0400
namespace facts

updated action plugins to use new guranteed facts
updated tests to new data clean
added cases for ansible_local and some docstrings

revision   rev_idx median run1  run2  run3  run4  run5  run6
ee80215fa9 965     55572  56028 55572 55644
9c629f8a1c 966     55580  56004 55580 55740
76202bc7c3 967     55756  56100 55756 55848
fedd1779cc 968     55676  56028 55940 55676
db749de5b8 969     55736  56036 55736 55868
e0cb54a2aa 970     53422  53772 53388 53256 53648 53432 53412
f1fe467c22 971     53180  53684 53568 53180
4443da2d79 972     53148  53772 53148 53964
4464635787 973     53408  53660 53456 53408
356901b72d 974     53328  53700 53328 53504
38444bb76c 975     53216  53540 53492 53216

ssuchter · 2018-01-08T19:14:43Z

This (very recent) commit improves (lowers) RAM usage somewhat:

commit 46263d7
Author: Nathaniel Case this.is@nathanielca.se
Date: Mon Jan 8 10:56:47 2018 -0500
Fixes for nxos_config integration tests (#34579)

* deletage_to: localhost -> connection: local

* Fix test setup

revision   rev_idx median run1  run2  run3  run4  run5  run6  run7  run8  run9  run10 run11 run12
46263d77f1 1       51718  51848 51592 51688 51748 51228 51864 52188 51812 51140 51804 51684 51336
42dd48a6d0 2       56924  57356 56924 56984
473b2d58ec 3       56728  57380 56728 57100
ad73bda323 4       56864  57160 56864 56924
943107b1b9 5       56840  57320 56920 56840

ssuchter · 2018-01-08T19:46:54Z

Ok, I re-looked through all of these commits and ran a more extensive test case (5x number of loops for playbook includes). This was designed to exacerbate the memory "leak" as opposed to things that just increase memory usage by something more fixed.

I'm convinced that we should be looking at this commit:

commit 6ba6819
Author: James Cammarata jimi@sngx.net
Date: Thu Dec 8 01:16:08 2016 -0500

Re-adding the init py for modules

I have no idea why such a change causes such a huge difference, but it's clearly gigantic. This change increased the memory for my test case (that does 500 includes inside 3 nested loops of a trivial task list (just calls debug once and prints out the loop index numbers) by over 4x. (88Mb)

These memory numbers are not comparable to the earlier ones I was posting. Those were all with 100 includes, this is with 500 includes:

revision   rev_idx median run1   run2   run3   run4   run5   run6
46263d77f1 1       126900 127848 128656 126900
42dd48a6d0 2       127824 127844 128568 127824
db749de5b8 969     125660 126380 125660 126696
e0cb54a2aa 970     122744 123072 122872 122744
78478e80ea 4806    114624 114956 114624 114852
409fe1a3c3 4807    135952 136032 136072 135952
a108f0fcd3 5037    135916 136484 135916 135956
74e385e43a 5038    132772 132960 132772 132880
3d65482927 6004    133080 133080 133128 133264
40235d7b99 6005    114296 114588 114636 114296
dd0257b995 7193    115352 115352 115524 115492
7faa041636 7194    113092 114652 113092 114280
1c9a58a885 7407    113364 114768 113904 113364
fa5386c488 7408    114296 114608 114296 114300
6ba6819446 7409    114304 114612 114292 113232 114740 114308 114300
0b47c908eb 7410    25714  26328  25660  25716  26204  25524  25712
250b0dff46 7411    25520  26288  25584  25520
cb1888125d 7412    25584  26352  25584  25680
5628e260f2 7413    25468  26208  25656  25468

I also checked that there aren't any weird cross-branch things going on. E.g. there is a direct parent commit chain going on:

1c9a58a -> fa5386c -> 6ba6819 -> 0b47c90 -> 250b0df -> cb18881 -> 5628e26 -> 573078f

ssuchter · 2018-01-08T20:25:19Z

Attached is the trivial playbook setup that I used to reproduce this issue. memory_leak.yml does 100 includes, memory_leak2.yml does 600 includes (not 500 as I noted above, oops)

ansible_memory_leak.zip

cdman · 2018-01-09T06:00:13Z

@ssuchter - thank you for your time in putting together these tests! Hope that this will make fixing the issue faster (since I can't upgrade Ansible until it's fixed).

ssuchter · 2018-01-09T07:15:36Z

Ok, some of those previous results (in particular, the pointing at commit 6ba6819) was wrong. That commit was showing up as a big user because ansible was actually crashing without it, but my test harness didn't catch that and so thought the crashed ansible didn't take much RAM.

I re-ran everything, and found (with 600 includes) some commits that appear to be very costly:

Commit e238ae9 hurts to the tune of 6%. Not huge.
Commit 78478e8 helps to the tune of 19%. Good!
Commit 390be19 hurts to the tune of 17%. Bad!
and last, but certainly not least:
Commit 47acf55 hurts to the tune of 57%. Very bad!!

This is commit 47acf55:

Cache tasks by uuid in PlayIterator for O(1) lookups

Rather than repeatedly searching for tasks by uuid via iterating over
all known blocks, cache the tasks when they are added to the PlayIterator
so the lookup becomes a simple key check in a dict.

Here's the memory usage before and after that commit:

revision   rev_idx median delta run1   run2   run3   run4   run5
47acf55fa9 14760   100184 -0.57 100312 100184 100520 100180 100404
125c53e691 14761   43280  -0.00 43280  43232  43308  43316  43304

The obvious thing to look at in that commit is if anything gets cached in self._task_uuid_cache that didn't get added to self._blocks. There are two bits of code I'm suspicious of:

These lines in 192-193 - they seem to cache something from self._play.handlers that isn't in self._blocks:

for handler_block in self._play.handlers:
    self.cache_block_tasks(handler_block)

These lines in add_tasks, lines 573-574. It doesn't seem like these gets added to self._blocks either:

for b in task_list:
    self.cache_block_tasks(b)

This also moves the task caching from the PlayIterator to the StrategyBase class, where it makes more sense (and makes it easier to not have to change the strategy class methods leading to an API change). Fixes ansible#31673

* Cache tasks as they are queued instead of en masse This also moves the task caching from the PlayIterator to the StrategyBase class, where it makes more sense (and makes it easier to not have to change the strategy class methods leading to an API change). Fixes #31673 * Cleaning up unit tests due to 502ca78

* Cache tasks as they are queued instead of en masse This also moves the task caching from the PlayIterator to the StrategyBase class, where it makes more sense (and makes it easier to not have to change the strategy class methods leading to an API change). Fixes ansible#31673 * Cleaning up unit tests due to 502ca78 (cherry picked from commit b107e39)

* Cache tasks as they are queued instead of en masse This also moves the task caching from the PlayIterator to the StrategyBase class, where it makes more sense (and makes it easier to not have to change the strategy class methods leading to an API change). Fixes #31673 * Cleaning up unit tests due to 502ca78 (cherry picked from commit b107e39)

joshperry · 2018-01-17T09:26:08Z

This did help quite a bit, but we are still getting OOM killed. Perhaps not related to this at all, but these are running with 2.4.1.0 on alpine 3.7 and then stable-2.4 branch with this backport. The playbook takes about 1.5 minutes with 10 forks, there are about 600 hosts.

zerkms · 2018-01-17T09:34:20Z

My 2 cents, an educated guess:

given that the ansible uses multiprocess fork-based model when another fork is created the memory is COW'ed (copy-on-write). That effectively is a cheap operation, both in terms of cpu and memory actually mapped/allocated to the process.

What happens next is - every fork uses their "cloned" memory, which leads to the actual memory copy operation, which is not bad still.

But, then GC triggers and entirely re-shuffles the python's process (each of those, obviously at random points in time, depending on a particular fork memory usage patterns) managed memory, which leads to a huge spike, since a lot of pages are touched and modified.

joshperry · 2018-01-17T09:38:45Z

The inventory file has a channel variable set for each host, and then we have different playbooks that we include depending on the host channel.

playbook.yml

- hosts: panels
  serial: 10
  tasks:
  - include_role:
      name: panels

roles/panels/main.yaml

# Run playbook specific to the channel
- include_tasks: "{{ channel }}.yaml"

production.yaml

- include_tasks: fstrim-cron.yaml
- include_tasks: sd-info.yaml

fstrim-cron.yaml

- name: copy fstrim timer unit
  copy: src=etc/systemd/system/fstrim.timer dest=/etc/systemd/system/fstrim.timer owner=root group=root mode=0644
  become: true

- name: copy fstrim service unit
  copy: src=etc/systemd/system/fstrim.service dest=/etc/systemd/system/fstrim.service owner=root group=root mode=0644
  become: true

- name: enable the fstrim timer
  systemd:
    name: fstrim.timer
    state: started
    enabled: true
  register: enable_timer
  become: true

- name: run first fstrim
  systemd:
    name: fstrim.service
    state: started
  when: enable_timer.changed
  become: true

sd-info.yaml

- name: Get SD card oemid
  shell: cat /sys/class/mmc_host/mmc0/mmc0\:*/oemid
  register: sd_oemid

- name: Get SD card name
  shell: cat /sys/class/mmc_host/mmc0/mmc0\:*/name
  register: sd_name

- name: Save SD card info in panel meta
  shell: "python scripts/save_sd_info.py {{panel_id}} \"{{sd_oemid.stdout_lines[0]}}\" \"{{sd_name.stdout_lines[0]}}\""
  delegate_to: 127.0.0.1

joshperry · 2018-01-17T09:42:50Z

@zerkms One thing I did neglect to mention is that the spikes correlated with the include_role happening in the logs just after Gathering facts. And as each group of hosts were run through the playbook, that step would take longer and longer each time, eventually taking longer than the playbook itself. The dips roughly correlated with when the playbook was actually executing.

zerkms · 2018-01-17T09:46:24Z

@joshperry my personal research shows that include_role and other similar importing tasks cause ~~a lot~~ some memory allocation, which causes GC to trigger and make a surge in the memory consumption.
My point above is that the actual allocation might be not that bad, but GC makes it much worse (since after it modifies large areas of memory the kernel actually performs the memory pages copying). (it's a guess though, but I'm 90% confident it's what happens).

cdman · 2018-01-17T10:35:01Z

@zerkms - That's certainly a good guess. I think Instagram battled a similar issue with their Django deployment which ended up with adding a new API to CPython: https://engineering.instagram.com/copy-on-write-friendly-python-garbage-collection-ad6ed5233ddf (unfortunately only 3.7).

joshperry · 2018-01-17T16:21:31Z

@zerkms Interesting, I'm going to try to put together a statically imported version of my playbooks and see if that helps with the GC. I'm assuming that even though these includes only distill down to 7 tasks, each dynamic task is considered unique since it is included, causing it to be more like 600 hosts * 7 tasks that GC has to grind through.

joshperry · 2018-01-17T18:37:18Z

Holy Hannah,
Let that be a cautionary tale that dynamic includes are a hairy beast.

This is my same playbook with the channels functionality moved to host groups and with serial:20.

jimi-c · 2018-01-18T17:26:39Z

@joshperry there was another issue fixed by c30ee42 which should address this and is being included in 2.4.3 rc3. You can test it there, or give devel a try if possible.

holta · 2018-02-12T05:59:42Z

Just FYI those who are running out of memory as a result of Ansible 2.4.3 on Raspberry Pi ("OSError: [Errno 12] Cannot allocate memory") should revert to Ansible 2.4.2 as Internet-in-a-Box has done successfully.

sivel · 2018-02-12T18:15:11Z

@holta we recently addressed another issue with memory allocation in #35796

That change will be included in an upcoming 2.4.4 release and is in stable-2.4, 2.5.0.b1 and devel currently.

marcindulak · 2018-02-16T11:21:24Z

My impression is also that the memory issues pop up when using include_role.
I have a small set of 2 (!) target hosts and a playbook with about a dozen of include_role that make use of both tasks_from and vars_from, in total about 1000 tasks per host are executed.
However I've not been able to isolate the memory problem by simplifying the set of include_role tasks.

Preparing for what's coming in the future I took the latest today's devel 9018c63 and I see the following.

While CentOS7 ansible 2.4.2.0 manages most of the time (apart from a rare "A worker was found in a dead state") to execute the same playbook over and over again (against 2 hosts) using 2GB or RAM, the latest ansible devel only passes without "Cannot allocate memory" on a 6GB ansible host.

Can anyone confirm/disprove the current state of the "Cannot allocate memory" worsening in devel?

holta · 2018-03-25T21:37:37Z

@sivel this issue (or #35796 or similar?) has returned on Ansible 2.5.0 on Raspbian 2018-03-13 on Raspberry Pi 3. As documented at iiab/iiab#669 (comment) :

TASK [network : Copy /etc/sysconfig/dhcpd file] ********************************
An exception occurred during task execution. To see the full traceback, use -vvv. The error was: OSError: [Errno 12] Cannot allocate memory
fatal: [127.0.0.1]: FAILED! => {"msg": "Unexpected failure during module execution.", "stdout": ""}

ansibot added affects_2.4 This issue/PR affects Ansible v2.4 bug_report needs_triage Needs a first human triage before being processed. support:core This issue/PR relates to code supported by the Ansible Engineering Team. labels Oct 12, 2017

s-hertel removed the needs_triage Needs a first human triage before being processed. label Oct 13, 2017

cdman mentioned this issue Nov 13, 2017

Ansible 2.4.1.0 fails with "[Errno 12] Cannot allocate memory" #32854

Closed

ansibot added deprecated This issue/PR relates to a deprecated module. module This issue/PR relates to a module. labels Nov 21, 2017

This was referenced Jan 6, 2018

Nested includes cause "exponential" growth of consumed memory #27024

Closed

memory leak when using loop_control: label: "" #32537

Closed

include_role in a loop: huge memory usage and cpu consumption #33183

Closed

jimi-c mentioned this issue Jan 11, 2018

Cache tasks as they are queued instead of en masse #34752

Merged

jimi-c closed this as completed in #34752 Jan 15, 2018

holta mentioned this issue Feb 10, 2018

is Ansible 2.4.3 running out of memory when installing IIAB 6.5/master on RPi3? iiab/iiab#669

Closed

ansibot added bug This issue/PR relates to a bug. and removed bug_report labels Mar 7, 2018

holta mentioned this issue Mar 25, 2018

Increased memory usage in ansible-playbook from 2.4.2 to 2.4.3 #35796

Closed

ansible locked and limited conversation to collaborators Apr 26, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Memory Allocated for Included Tasks is Never Recovered #31673

Memory Allocated for Included Tasks is Never Recovered #31673

mrstevek commented Oct 12, 2017 •

edited

rahimkhoja commented Oct 26, 2017 •

edited

mrstevek commented Oct 27, 2017

alikins commented Dec 15, 2017

ssuchter commented Jan 6, 2018

ssuchter commented Jan 8, 2018

maxamillion commented Jan 8, 2018

ssuchter commented Jan 8, 2018 via email

maxamillion commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018 •

edited

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

cdman commented Jan 9, 2018

ssuchter commented Jan 9, 2018

joshperry commented Jan 17, 2018

zerkms commented Jan 17, 2018 •

edited

joshperry commented Jan 17, 2018

joshperry commented Jan 17, 2018 •

edited

zerkms commented Jan 17, 2018 •

edited

cdman commented Jan 17, 2018

joshperry commented Jan 17, 2018 •

edited

joshperry commented Jan 17, 2018

jimi-c commented Jan 18, 2018 •

edited

holta commented Feb 12, 2018

sivel commented Feb 12, 2018

marcindulak commented Feb 16, 2018

holta commented Mar 25, 2018

Memory Allocated for Included Tasks is Never Recovered #31673

Memory Allocated for Included Tasks is Never Recovered #31673

Comments

mrstevek commented Oct 12, 2017 • edited

ISSUE TYPE

COMPONENT NAME

ANSIBLE VERSION

CONFIGURATION

OS / ENVIRONMENT

SUMMARY

STEPS TO REPRODUCE

EXPECTED RESULTS

ACTUAL RESULTS

rahimkhoja commented Oct 26, 2017 • edited

mrstevek commented Oct 27, 2017

alikins commented Dec 15, 2017

ssuchter commented Jan 6, 2018

ssuchter commented Jan 8, 2018

maxamillion commented Jan 8, 2018

ssuchter commented Jan 8, 2018 via email

maxamillion commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018 • edited

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

ssuchter commented Jan 8, 2018

cdman commented Jan 9, 2018

ssuchter commented Jan 9, 2018

joshperry commented Jan 17, 2018

zerkms commented Jan 17, 2018 • edited

joshperry commented Jan 17, 2018

joshperry commented Jan 17, 2018 • edited

zerkms commented Jan 17, 2018 • edited

cdman commented Jan 17, 2018

joshperry commented Jan 17, 2018 • edited

joshperry commented Jan 17, 2018

jimi-c commented Jan 18, 2018 • edited

holta commented Feb 12, 2018

sivel commented Feb 12, 2018

marcindulak commented Feb 16, 2018

holta commented Mar 25, 2018

mrstevek commented Oct 12, 2017 •

edited

rahimkhoja commented Oct 26, 2017 •

edited

ssuchter commented Jan 8, 2018 •

edited

zerkms commented Jan 17, 2018 •

edited

joshperry commented Jan 17, 2018 •

edited

zerkms commented Jan 17, 2018 •

edited

joshperry commented Jan 17, 2018 •

edited

jimi-c commented Jan 18, 2018 •

edited