Absinthe: Absinthe.Subscription.Proxy possible memory leak

[mjquinlan2000]

I have absinthe running on a production server with Kubernetes. It appears that the Absinthe.Subscription.Proxy services are growing in memory uncontrollably and eventually cause the Kubernetes pod to reach it's memory limit (1GiB) and crash. This is a huge problem for my company as we heavily rely on subscriptions to prevent overfetching on our mobile applications. Also we have a lot of distributed caching and processes that need to be restarted when a pod goes down. I traced this by running:

iex(my_cluster@ip)> :recon.proc_count(:memory, 5) |> Enum.map(&elem(&1, 0)) |> Enum.map(&:recon.info/1)

[
  [
    meta: [
      registered_name: MyApp.GlobalPubSub,
      dictionary: [
        "$initial_call": {Phoenix.PubSub.PG2Server, :init, 1},
        "$ancestors": [MyApp.GlobalPubSub.Supervisor, MyAppWeb.Endpoint,
         MyApp.Supervisor, #PID<0.3713.0>]
      ],
      group_leader: #PID<0.3712.0>,
      status: :waiting
    ],
    signals: [
      links: [#PID<0.3756.0>],
      monitors: [],
      monitored_by: [#PID<56147.3716.0>, #PID<56151.3716.0>, #PID<0.3716.0>],
      trap_exit: false
    ],
    location: [
      initial_call: {:proc_lib, :init_p, 5},
      current_stacktrace: [
        {:gen_server, :loop, 7, [file: 'gen_server.erl', line: 394]},
        {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}
      ]
    ],
    memory_used: [
      memory: 395088576,
      message_queue_len: 0,
      heap_size: 22177879,
      total_heap_size: 49385921,
      garbage_collection: [
        max_heap_size: %{error_logger: true, kill: true, size: 0},
        min_bin_vheap_size: 46422,
        min_heap_size: 233,
        fullsweep_after: 65535,
        minor_gcs: 3
      ]
    ],
    work: [reductions: 3009125]
  ],
  [
    meta: [
      registered_name: [],
      dictionary: [
        "$initial_call": {Absinthe.Subscription.Proxy, :init, 1},
        "$ancestors": [#PID<0.3919.0>, #PID<0.3913.0>, MyApp.Supervisor,
         #PID<0.3713.0>]
      ],
      group_leader: #PID<0.3712.0>,
      status: :waiting
    ],
    signals: [
      links: [#PID<0.3919.0>],
      monitors: [],
      monitored_by: [#PID<0.3793.0>],
      trap_exit: false
    ],
    location: [
      initial_call: {:proc_lib, :init_p, 5},
      current_stacktrace: [
        {:gen_server, :loop, 7, [file: 'gen_server.erl', line: 394]},
        {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}
      ]
    ],
    memory_used: [
      memory: 325276576,
      message_queue_len: 0,
      heap_size: 18481566,
      total_heap_size: 40659445,
      garbage_collection: [
        max_heap_size: %{error_logger: true, kill: true, size: 0},
        min_bin_vheap_size: 46422,
        min_heap_size: 233,
        fullsweep_after: 65535,
        minor_gcs: 1
      ]
    ],
    work: [reductions: 555787]
  ],
  [
    meta: [
      registered_name: [],
      dictionary: [
        "$initial_call": {Absinthe.Subscription.Proxy, :init, 1},
        "$ancestors": [#PID<0.3919.0>, #PID<0.3913.0>, MyApp.Supervisor,
         #PID<0.3713.0>]
      ],
      group_leader: #PID<0.3712.0>,
      status: :waiting
    ],
    signals: [
      links: [#PID<0.3919.0>],
      monitors: [],
      monitored_by: [#PID<0.3778.0>],
      trap_exit: false
    ],
    location: [
      initial_call: {:proc_lib, :init_p, 5},
      current_stacktrace: [
        {:gen_server, :loop, 7, [file: 'gen_server.erl', line: 394]},
        {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}
      ]
    ],
    memory_used: [
      memory: 250539352,
      message_queue_len: 0,
      heap_size: 18481566,
      total_heap_size: 31317292,
      garbage_collection: [
        max_heap_size: %{error_logger: true, kill: true, size: 0},
        min_bin_vheap_size: 46422,
        min_heap_size: 233,
        fullsweep_after: 65535,
        minor_gcs: 2
      ]
    ],
    work: [reductions: 715806]
  ],
  [
    meta: [
      registered_name: [],
      dictionary: [
        "$initial_call": {Absinthe.Subscription.Proxy, :init, 1},
        "$ancestors": [#PID<0.3919.0>, #PID<0.3913.0>, MyApp.Supervisor,
         #PID<0.3713.0>]
      ],
      group_leader: #PID<0.3712.0>,
      status: :waiting
    ],
    signals: [
      links: [#PID<0.3919.0>],
      monitors: [],
      monitored_by: [#PID<0.3772.0>],
      trap_exit: false
    ],
    location: [
      initial_call: {:proc_lib, :init_p, 5},
      current_stacktrace: [
        {:gen_server, :loop, 7, [file: 'gen_server.erl', line: 394]},
        {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}
      ]
    ],
    memory_used: [
      memory: 177424048,
      message_queue_len: 0,
      heap_size: 22177879,
      total_heap_size: 22177879,
      garbage_collection: [
        max_heap_size: %{error_logger: true, kill: true, size: 0},
        min_bin_vheap_size: 46422,
        min_heap_size: 233,
        fullsweep_after: 65535,
        minor_gcs: 0
      ]
    ],
    work: [reductions: 828951]
  ],
  [
    meta: [
      registered_name: [],
      dictionary: [
        "$initial_call": {Absinthe.Subscription.Proxy, :init, 1},
        "$ancestors": [#PID<0.3919.0>, #PID<0.3913.0>, MyApp.Supervisor,
         #PID<0.3713.0>]
      ],
      group_leader: #PID<0.3712.0>,
      status: :waiting
    ],
    signals: [
      links: [#PID<0.3919.0>],
      monitors: [],
      monitored_by: [#PID<0.3790.0>],
      trap_exit: false
    ],
    location: [
      initial_call: {:proc_lib, :init_p, 5},
      current_stacktrace: [
        {:gen_server, :loop, 7, [file: 'gen_server.erl', line: 394]},
        {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}
      ]
    ],
    memory_used: [
      memory: 51089736,
      message_queue_len: 0,
      heap_size: 6189440,
      total_heap_size: 6386090,
      garbage_collection: [
        max_heap_size: %{error_logger: true, kill: true, size: 0},
        min_bin_vheap_size: 46422,
        min_heap_size: 233,
        fullsweep_after: 65535,
        minor_gcs: 6
      ]
    ],
    work: [reductions: 120971]
  ]
]

This uses recon to get the top 5 processes with the highest memory and then display their info. As you can see the top process is our global pubsub which is a Phoenix PG2 pubsub process. Each one of the Absinthe.Subscription.Proxy processes are chewing up 200 MiB+ of memory though and they keep growing.

When I get the state of each process it looks like this:

iex(my_cluster@ip)> :recon.proc_count(:memory, 5) |> Enum.map(&elem(&1, 0)) |> Enum.map(&:sys.get_state/1)

[
  %{name: MyApp.GlobalPubSub, pool_size: 12},
  %Absinthe.Subscription.Proxy{pubsub: MyAppWeb.Endpoint},
  %Absinthe.Subscription.Proxy{pubsub: MyAppWeb.Endpoint},
  %Absinthe.Subscription.Proxy{pubsub: MyAppWeb.Endpoint}
]

As you can see it doesn't look like the state has anything to do with the memory allocation as it's just simple structs. You might have also noticed that the :message_queue_len of all of those processes is 0 so it's not allocating memory there.

Any help at all on this would be greatly appreciated.

Thank you!

[benwilson512]

Interesting. So, the Proxy processes hold literally 0 state, other than the name of the pubsub and the name of the node they're supposed to look for. Even the actual publication happens in a task spawned explicitly for that purpose.

One conceivable thing could be binary memory, I'm not familiar enough with Recon's output to tell if heap is 100% just process heap or if it could include ref counted binaries. One way to find out would be, next time the node is using a lot of memory:

1) remote console into the node
2) Process.list |> Enum.each(&:erlang.garbage_collect/1)

If that helps, we could look at adding an occasional garbage collection call to the proxy process on a timer.

None of that explains why the PubSub process itself is showing high memory usage though. Do you have a sense of how many publications / hour you're doing, how many simultaneous users you have, etc?

Edit: Please provide the output of: mix deps|grep phoenix and mix deps|grep absinthe.

[mjquinlan2000]

So the &:erlang.garbage_collect/1 call did not free up any memory. Here's the outputs:

$ mix deps | grep phoenix

* phoenix_pubsub 1.1.2 (Hex package) (mix)
  locked at 1.1.2 (phoenix_pubsub) 496c303b
* phoenix 1.4.9 (Hex package) (mix)
  locked at 1.4.9 (phoenix) 746d098e
* absinthe_phoenix 1.4.4 (Hex package) (mix)
  locked at 1.4.4 (absinthe_phoenix) af3b7b44
* phoenix_live_reload 1.2.1 (Hex package) (mix)
  locked at 1.2.1 (phoenix_live_reload) 274a4b07
* phoenix_ecto 4.0.0 (Hex package) (mix)
  locked at 4.0.0 (phoenix_ecto) c43117a1

and

$ mix deps | grep absinthe

* absinthe 1.4.16 (Hex package) (mix)
  locked at 1.4.16 (absinthe) 0933e4d9
* absinthe_ecto 0.1.3 (Hex package) (mix)
  locked at 0.1.3 (absinthe_ecto) 420b6812
* absinthe_relay 1.4.6 (Hex package) (mix)
  locked at 1.4.6 (absinthe_relay) ec0e2288
* absinthe_plug 1.4.7 (Hex package) (mix)
  locked at 1.4.7 (absinthe_plug) 939b6b9e
* absinthe_phoenix 1.4.4 (Hex package) (mix)
  locked at 1.4.4 (absinthe_phoenix) af3b7b44

I'm not exactly sure how many users/subscriptions we have active at any point in time. We just started to put them in a lot of places, but the number of users actively using devices has to be below 10,000

[mjquinlan2000]

Actually I misspoke. The processes are significantly smaller after the garbage collection. I accidentally misread the output when I did it the first time. I'm wondering if part of the problem might be with Phoenix.PubSub as well. I'm going to dig into this deeper to see if I can get more meaningful stats on what's not being garbage collected.

Edit: Here's an image of what our Sysdig monitors say after garbage collection was done on api-5b7b87b6-lhtw2. You can see there's a huge drop in memory usage.

[benwilson512]

Interesting, my guess is ref counted binaries being the culprit. I'll put up a PR that adds an auto GC call.

[benwilson512]

Based on that image, are you seeing that one specific API server grows substantially in memory while the others do not? Or do all three grow?

[mjquinlan2000]

@benwilson512 all three of them grow. I think that they're just out of sync since we deployed on Friday.

[jwaldrip]

@benwilson512 any update on this? We are still seeing a significant amount of pod restarts.

[benwilson512]

@jwaldrip is that a recent happening? or are you just starting with subscriptions?

[benwilson512]

Absinthe master now contains does an every 5 second GC of the proxy processes. This isn't an ideal solution but it may help.

[mjquinlan2000]

@benwilson512 thanks for that. I feel like this is more or less a band-aid though and I would like to help figure out what the actual problem is. Do you have any suggestions for where to start when trying to figure out these types of memory leaks? It's something I have never seen before and I've not really found anything that great in terms of helpful articles on the internet.

[benwilson512]

Well, this is a not uncommon thing to need to do with "pass through" type processes. It's covered in Erlang in Anger section 7.2 https://s3.us-east-2.amazonaws.com/ferd.erlang-in-anger/text.v1.1.0.pdf

To quote, binary memory leaks happen when proceses:

1. do too little work to warrant allocations and garbage collection;
2. eventually grow a large stack or heap with various data structures, collect them, then
   get to work with a lot of refc binaries. Filling the heap again with binaries (even
   though a virtual heap is used to account for the refc binaries’ real size) may take a
   lot of time, giving long delays between garbage collections.

However the more I think about it the more confused I am. The binaries involved in the proxy process should be small. The messages that a proxy receives are:

  %{
      node: node_name(otp_app, endpoint),
      subscribed_fields: subscribed_fields,
      mutation_result: mutation_result
    }

Where subscribed_fields is simply stuff like shipment_updated: "#{shipment.id}" and mutation_result is whatever value you're publishing. Unless mutation_result has large binaries it shouldn't be an issue. If mutation_result DOES have large binaries, then there could maybe be an issue.

[mjquinlan2000]

Ok I will try to work through it some more either today or next week. I didn't want to pull in Absinthe master so I just put a fix in that garbage collects the top 5 memory-consuming Proxy processes every 5 seconds. Thanks for your help on this.

[jwaldrip]

Even though @mjquinlan2000 did this, we are still seeing OOM issues. This leads me to believe that something is holding on to references. GC will only work if that is not the case. @benwilson512 could really use a fix or at least some insight.

[mjquinlan2000]

@benwilson512 I've been at this all day today. I put a trace call on &Absinthe.Subscription.Proxy.handle_info/2 call on our production servers and all of the arguments that I can see do not have large binaries attached. The most passed mutation result is just our user structs which are Ecto structs. I will keep digging in to see if I can get some better insight.

[benwilson512]

Update: I've definitely reproduced the issue where subscription documents take up too much space. I'll be pushing a change today that tries to minimize the space consumed by the :ets table per document.

While I haven't been able to reproduce the issue where the proxy processes get very large, I will nonetheless be restructuring how the supervision tree works. Right now the proxy processes do a Task.start_link for each incoming document. I'm going to instead have a task supervisor that I'll spawn each task under. Perhaps by following OTP conventions more closely it'll have the side effect of clearing up the memory growth over time that some of you are also observing.

[benwilson512]

Further update: PR for 5x memory improvement is up: https://github.com/absinthe-graphql/absinthe/pull/775. There is reason to believe that memory improvement could be made closer to 25x, but there seem to be some subtleties about writing to :ets that are making this a bit tricky.

The main sticking point for all of this is the need to preserve the pipeline that was used to process the subscription. If we are not keeping the blueprint around, we need to be able to deterministically create the same blueprint over and over, and that means we need the exact input, and the exact pipeline. Storing the pipeline is taking up more space than I expected, see the PR for details.

The PR does pass the test suite, and I've tested it with our own applications as well. HOWEVER if you rely heavily on context based deduplication do not use it, as that is temporarily disabled within that branch. If you don't know what context based deduplication is, you probably aren't using it. I would appreciate it if one or more of the people experiencing memory issues could give it a whirl and see if it helps.

[mjquinlan2000]

@benwilson512 I'm trying to use the branch from the PR you submitted and I can't seem to get it to work. I'm getting a weird error about :type_definitions:

== Compilation error in file lib/myapp_graphql/worker/schema.ex ==
** (KeyError) key :type_definitions not found in: %Absinthe.Blueprint.Schema.ObjectTypeDefinition{__private__: [], __reference__: %{location: %{file: "/Users/mquinlan/Workspace/MyApp/monorepo/services/api/lib/myapp_graphql/worker/schema.ex", line: 58}, module: MyAppGraphQL.Schema.Worker}, description: nil, directives: [], errors: [], fields: [%Absinthe.Blueprint.Schema.FieldDefinition{__private__: [meta: [absinthe_telemetry: true]], __reference__: %{location: %{file: "/Users/mquinlan/Workspace/MyApp/monorepo/services/api/lib/myapp_graphql/worker/schema.ex", line: 66}, module: MyAppGraphQL.Schema.Worker}, arguments: [], complexity: nil, config: nil, default_value: nil, deprecation: nil, description: "Query the currently authenticated user.", directives: [], errors: [], flags: %{}, function_ref: {:query, :viewer}, identifier: :viewer, middleware: [{:{}, [], [{MyAppGraphQL.Common.Middleware.EnsureUser, :call}, []]}, {:{}, [], [{Absinthe.Resolution, :call}, {:&, [line: 69], [{:/, [line: 69], [{{:., [line: 69], [{:__aliases__, [counter: {MyAppGraphQL.Schema.Worker, 122}, line: 69], [:Resolver, :Schema]}, :viewer]}, [line: 69], []}, 2]}]}]}], module: MyAppGraphQL.Schema.Worker, name: "viewer", source_location: nil, triggers: {:%{}, [], []}, type: :worker}, %Absinthe.Blueprint.Schema.FieldDefinition{__private__: [meta: [absinthe_telemetry: true]], __reference__: %{location: %{file: "/Users/mquinlan/Workspace/MyApp/monorepo/services/api/lib/myapp_graphql/worker/schema.ex", line: 59}, module: MyAppGraphQL.Schema.Worker}, arguments: [%Absinthe.Blueprint.Schema.InputValueDefinition{__private__: [], __reference__: %{location: %{file: "/Users/mquinlan/Workspace/MyApp/monorepo/services/api/lib/myapp_graphql/worker/schema.ex", line: 59}, module: MyAppGraphQL.Schema.Worker}, default_value: {:unquote, [], [nil]}, default_value_blueprint: nil, deprecation: nil, description: "The id of an object.", directives: [], errors: [], flags: %{}, identifier: :id, module: MyAppGraphQL.Schema.Worker, name: "id", placement: :argument_definition, source_location: nil, type: %Absinthe.Blueprint.TypeReference.NonNull{errors: [], of_type: :id}}], complexity: nil, config: nil, default_value: nil, deprecation: nil, description: nil, directives: [], errors: [], flags: %{}, function_ref: {:query, :node}, identifier: :node, middleware: [{:{}, [], [{Absinthe.Relay.Node, :resolve_with_global_id}, []]}, {:{}, [], [{MyAppGraphQL.Common.Middleware.EnsureUser, :call}, []]}, {:{}, [], [{Absinthe.Resolution, :call}, {:&, [line: 62], [{:/, [line: 62], [{{:., [line: 62], [{:__aliases__, [counter: {MyAppGraphQL.Schema.Worker, 122}, line: 62], [:Resolver, :Schema]}, :node_field]}, [line: 62], []}, 2]}]}]}], module: MyAppGraphQL.Schema.Worker, name: "node", source_location: nil, triggers: {:%{}, [], []}, type: :node}], flags: %{}, identifier: :query, imports: [my_queries: [], my_worker_queries: [], skill_queries: []], interface_blueprints: [], interfaces: [], is_type_of: nil, module: MyAppGraphQL.Schema.Worker, name: "RootQueryType", source_location: nil}
    (stdlib) :maps.get(:type_definitions, %Absinthe.Blueprint.Schema.ObjectTypeDefinition{__private__: [], __reference__: %{location: %{file: "/Users/mquinlan/Workspace/MyApp/monorepo/services/api/lib/myapp_graphql/worker/schema.ex", line: 58}, module: MyAppGraphQL.Schema.Worker}, description: nil, directives: [], errors: [], fields: [%Absinthe.Blueprint.Schema.FieldDefinition{__private__: [meta: [absinthe_telemetry: true]], __reference__: %{location: %{file: "/Users/mquinlan/Workspace/MyApp/monorepo/services/api/lib/myapp_graphql/worker/schema.ex", line: 66}, module: MyAppGraphQL.Schema.Worker}, arguments: [], complexity: nil, config: nil, default_value: nil, deprecation: nil, description: "Query the currently authenticated user.", directives: [], errors: [], flags: %{}, function_ref: {:query, :viewer}, identifier: :viewer, middleware: [{:{}, [], [{MyAppGraphQL.Common.Middleware.EnsureUser, :call}, []]}, {:{}, [], [{Absinthe.Resolution, :call}, {:&, [line: 69], [{:/, [line: 69], [{{:., [line: 69], [{:__aliases__, [counter: {MyAppGraphQL.Schema.Worker, 122}, line: 69], [:Resolver, :Schema]}, :viewer]}, [line: 69], []}, 2]}]}]}], module: MyAppGraphQL.Schema.Worker, name: "viewer", source_location: nil, triggers: {:%{}, [], []}, type: :worker}, %Absinthe.Blueprint.Schema.FieldDefinition{__private__: [meta: [absinthe_telemetry: true]], __reference__: %{location: %{file: "/Users/mquinlan/Workspace/MyApp/monorepo/services/api/lib/myapp_graphql/worker/schema.ex", line: 59}, module: MyAppGraphQL.Schema.Worker}, arguments: [%Absinthe.Blueprint.Schema.InputValueDefinition{__private__: [], __reference__: %{location: %{file: "/Users/mquinlan/Workspace/MyApp/monorepo/services/api/lib/myapp_graphql/worker/schema.ex", line: 59}, module: MyAppGraphQL.Schema.Worker}, default_value: {:unquote, [], [nil]}, default_value_blueprint: nil, deprecation: nil, description: "The id of an object.", directives: [], errors: [], flags: %{}, identifier: :id, module: MyAppGraphQL.Schema.Worker, name: "id", placement: :argument_definition, source_location: nil, type: %Absinthe.Blueprint.TypeReference.NonNull{errors: [], of_type: :id}}], complexity: nil, config: nil, default_value: nil, deprecation: nil, description: nil, directives: [], errors: [], flags: %{}, function_ref: {:query, :node}, identifier: :node, middleware: [{:{}, [], [{Absinthe.Relay.Node, :resolve_with_global_id}, []]}, {:{}, [], [{MyAppGraphQL.Common.Middleware.EnsureUser, :call}, []]}, {:{}, [], [{Absinthe.Resolution, :call}, {:&, [line: 62], [{:/, [line: 62], [{{:., [line: 62], [{:__aliases__, [counter: {MyAppGraphQL.Schema.Worker, 122}, line: 62], [:Resolver, :Schema]}, :node_field]}, [line: 62], []}, 2]}]}]}], module: MyAppGraphQL.Schema.Worker, name: "node", source_location: nil, triggers: {:%{}, [], []}, type: :node}], flags: %{}, identifier: :query, imports: [my_queries: [], my_worker_queries: [], skill_queries: []], interface_blueprints: [], interfaces: [], is_type_of: nil, module: MyAppGraphQL.Schema.Worker, name: "RootQueryType", source_location: nil})
    (elixir) lib/map.ex:273: Map.update!/3
    lib/absinthe/blueprint/schema.ex:188: Absinthe.Blueprint.Schema.build_types/3
    expanding macro: Absinthe.Schema.Notation.__before_compile__/1
    lib/myapp_graphql/worker/schema.ex:1: MyAppGraphQL.Schema.Worker (module)
    (elixir) lib/kernel/parallel_compiler.ex:229: anonymous fn/4 in Kernel.ParallelCompiler.spawn_workers/7

[benwilson512]

Can you show monorepo/services/api/lib/myapp_graphql/worker/schema.ex:58 and the surrounding area? Previous versions of Absinthe would generally ignore if things got put in the wrong place, the new version is more strict, but we haven't finalized the error messages yet.

[mjquinlan2000]

Hey @benwilson512 I finally got around to figuring out the compilation errors. The upgrade actually exposed a surprising amount of problems with our current schema that I had to fix. It's going out to our beta environment within the next couple of days. I'll let you know if we see any memory difference.

Edit:

For anyone wondering what the main problem was for this compilation error, I had to move the subscription do... and mutation do... blocks outside of the query do... block.

Before

query do
  subscription do
    # ... subscriptions
  end

  mutation do
    # ... mutations
  end
end

After:

query do
  # ... queries
end

subscription do
  # ... subscriptions
end

mutation do
  # ... mutations
end

[rhnonose]

We might be having this issue.
We're having memory peak and I got some glimpse through observer that Absinthe.Subscription.Proxy was consuming a lot of memory.
We've just updated to master and will give a feedback on memory usage.

[mjquinlan2000]

Hey @benwilson512 sorry for the late update; I rotated onto feature work since my last post.

We updated our production servers to:

      {:absinthe, "1.5.0-beta.2", override: true},
      {:absinthe_ecto, "~> 0.1.3"},
      {:absinthe_phoenix, "~> 1.4.0"},
      {:absinthe_plug, "~> 1.4.0"},
      {:absinthe_relay, "1.5.0-beta.0"},

1.5.0-beta.2 seems to have #775 merged in and we're not seeing a noticeable difference in the amount of pod crashes and sharp increases in memory usage. We've had it running in the wild for about 2 weeks now.

I don't know if I mentioned this before, but the error we're getting when a pod goes down is erl_child_setup closed which I inferred was an OOM problem because of our monitoring and what we noticed with the Absinthe.Subscription.Proxy processes chewing up large amounts of memory. Also, this thread suggested an OOM problem http://erlang.org/pipermail/erlang-questions/2017-February/091721.html

If you know any other reasons we might see this error, any insight would be much appreciated.

I'm going to try to find time this week to dig into it more. I'll keep you guys posted.

[benwilson512]

Interesting, so memory usage remains largely constant until the moment of crash, that doesn't sound like a memory leak to me. Memory leaks are usually characterized by a continuous slow memory growth up to the point of failure.

When you are measuring the amount of memory used by the proxy processes are you donig so during the period where everything is using ~1gb of ram of the period during which it's 3gigs of ram.

What are the various bars there?

[mjquinlan2000]

That's a good point. We're using Sysdig and I know there's a way to report top processes by various metrics, but I would have to write a custom reporter to report top erlang processes so I don't have to sit around and wait for an event to happen. I will work on getting that in this week.

[mjquinlan2000]

Ok I have some updates. I was able to log top process memory usage and segment by the process name and it turns out that our MyApp.PubSub processes were the offenders this time. I went and looked at the Phoenix.PubSub docs to see if I could find some answers. I didn't really get a confident answer, but I noticed that in our configs we had:

config :my_app, MyAppWeb.Endpoint,
  pubsub: [
    name: MyApp.PubSub,
    pool_size: System.schedulers_online(),
    adapter: Phoenix.PubSub.PG2
  ]

What stood out to me is that I had configured the pool size to be larger than 1 (the default) over a year ago. I hotfixed our production servers to use the default instead of System.schedulers_online(). Right after the release rolled out, I noticed that one of the nodes had a MyApp.PubSub running with 200 MiB of memory being used and another process MyApp.Endpoint.Registry.TaskSupervisor running with roughly the same amount of memory being used. They were both running with a lot of refc binaries. I garbage collected those 2 processes and I haven't seen any jump in about 16 hours at this point. It appears to me that the changes I made have made our cluster substantially more stable. I've been getting Pager Duty calls every 6 hours or so for the past 4 weeks and this is the first time since we noticed the problem that I haven't received a call at 4am.

I am, however, still concerned about that one process that ballooned _after_ the deploy so I will keep an eye on things through the weekend to see if it happens again. I know that the pubsub is currently only being used for absinthe subscriptions so it still might be related.

[benwilson512]

Well, the default is System.schedulers_online() |> Kernel./(4) |> Float.ceil() |> trunc(). That' 1 if you have < 8 vCPUs, higher if you have >= 8.

Setting that aside, Task.Supervisor using a lot of memory is definitely annoying, I guess I didn't realized that they were passed the actual start data, but I now see that they are. Let me evaluate some options with respect to that.

@mjquinlan2000 in the meantime you could consider starting a genserver process that calls :erlang.garbage_collect(pid) over every pubsub partition.

[mjquinlan2000]

@benwilson512 thanks for looking into it. I believe that it was pretty foolish of me to set the pubsub pool size to anything but the default considering that we're using an auto-scaling erlang cluster on our servers.

We have a hotfix going out right now to garbage collect the pubsub processes.

[benwilson512]

Hey @mjquinlan2000 are you still experiencing issues?

[mjquinlan2000]

Hey @benwilson512 sorry for the late response. Q4 got a little crazy. We are still experiencing intermittent pod restarts, but I'm 99% convinced it's not related to Absinthe and rather has something to do with the way we are using Swarm processes. It's not affecting our users (yet) so I've been focused on other things.

The work that you have done has definitely had a positive impact on memory usage on our servers. Thank you for the work you did on improving it. I will let you know if I notice anything else that I think may be related to Absinthe.