{"action":"created","issue":{"url":"https://api.github.com/repos/vernemq/vernemq/issues/988","repository_url":"https://api.github.com/repos/vernemq/vernemq","labels_url":"https://api.github.com/repos/vernemq/vernemq/issues/988/labels{/name}","comments_url":"https://api.github.com/repos/vernemq/vernemq/issues/988/comments","events_url":"https://api.github.com/repos/vernemq/vernemq/issues/988/events","html_url":"https://github.com/vernemq/vernemq/issues/988","id":386252204,"node_id":"MDU6SXNzdWUzODYyNTIyMDQ=","number":988,"title":"High memory usage even after test finishes","user":{"login":"szymonk","id":1737880,"node_id":"MDQ6VXNlcjE3Mzc4ODA=","avatar_url":"https://avatars0.githubusercontent.com/u/1737880?v=4","gravatar_id":"","url":"https://api.github.com/users/szymonk","html_url":"https://github.com/szymonk","followers_url":"https://api.github.com/users/szymonk/followers","following_url":"https://api.github.com/users/szymonk/following{/other_user}","gists_url":"https://api.github.com/users/szymonk/gists{/gist_id}","starred_url":"https://api.github.com/users/szymonk/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/szymonk/subscriptions","organizations_url":"https://api.github.com/users/szymonk/orgs","repos_url":"https://api.github.com/users/szymonk/repos","events_url":"https://api.github.com/users/szymonk/events{/privacy}","received_events_url":"https://api.github.com/users/szymonk/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":9,"created_at":"2018-11-30T16:12:47Z","updated_at":"2018-12-19T08:35:40Z","closed_at":null,"author_association":"NONE","body":"### Environment\r\n\r\n- VerneMQ Version: 7ea2de2bd4db01cbe9e678ef2653a831d7e3cf9a\r\n- OS: CentOS 7\r\n- Erlang/OTP version (if building from source): 21.1\r\n- VerneMQ configuration (vernemq.conf) or the changes from the default\r\n\r\n```\r\nallow_anonymous = off\r\nallow_register_during_netsplit = on\r\nallow_publish_during_netsplit = on\r\nallow_subscribe_during_netsplit = on\r\nallow_unsubscribe_during_netsplit = off\r\nallow_multiple_sessions = off\r\nmax_inflight_messages = 100\r\nmax_online_messages = 10000\r\nmax_offline_messages = 1000\r\nmax_message_size = 0\r\nupgrade_outgoing_qos = off\r\nlistener.max_connections = infinity\r\nlistener.nr_of_acceptors = 10\r\nsystree_enabled = off\r\nerlang.async_threads = 64\r\nerlang.max_ports = 262144\r\nleveldb.maximum_memory.percent = 8\r\nerlang.distribution.port_range.minimum = 6000\r\nerlang.distribution.port_range.maximum = 7999\r\nerlang.distribution_buffer_size = 10MB\r\nplumtree.outstanding_limit = 50000\r\n```\r\n\r\nWe also set +hmqd off_heap on erlang VM.\r\n\r\n### Expected behavior\r\n\r\nVerneMQ should need amount of memory which could be described in terms of parameters such as numer of clients, subscriptions, messages, nodes, etc.\r\n\r\n### Actual behaviour\r\n\r\nUsually memory usage on our VerneMQ nodes is about 6 GB. However, sometimes we are observing excessive usage of RAM that gets worse over time. It happens that 16 GB RAM + 32 GB of swap is not enough for handling 80k connections and vernemq is killed by the OS. \r\n\r\n#### Details\r\n\r\nOur setup:\r\n\r\n- 5 VerneMQ instances, 16GB RAM, 4 CPU each\r\n- haproxy as a load balancer (on a separate machine)\r\n- 28 mzbench nodes serving as MQTT clients\r\n\r\nTest scenario:\r\n\r\n- 400k clients (let's call them \"consumers\") connect to the cluster over 9 minutes with a constant rate. Each of them subscribes to a topic which is unique per client.\r\n- 1 special client (\"producer\") connects to the cluster. Once all the consumers are connected it starts to send messages to consumers' topics, one message per topic (client), 800 messages per second. The producer also subscribes to its own topic. This step of the test lasts for 15 minutes.\r\n  - Once a consumer receives a message from the producer, it sends the message back to the producer.\r\n- When the exchange of the messages is finished, all the clients gradually disconnect.\r\n\r\nHere are grafana charts showing memory and swap availability as well as network traffic and number of open tcp connections.\r\n![mem-available](https://user-images.githubusercontent.com/1737880/49297241-9c68ac00-f4ba-11e8-8223-35fc27af796c.png)\r\n![swap-free](https://user-images.githubusercontent.com/1737880/49297256-a5597d80-f4ba-11e8-96b0-bafed42421da.png)\r\n![cpu-load1](https://user-images.githubusercontent.com/1737880/49297364-e487ce80-f4ba-11e8-9a13-1043ae86c4cd.png)\r\n![tcp-connections](https://user-images.githubusercontent.com/1737880/49297389-f2d5ea80-f4ba-11e8-954c-a2cf5696ec23.png)\r\n![data-transfer](https://user-images.githubusercontent.com/1737880/49297394-f5384480-f4ba-11e8-851d-1fba08425473.png)\r\n\r\nOn the node which uses significantly more memory than the others, we could see the following log entries:\r\n\r\n```\r\n2018-11-29 13:26:42.655 [info] <0.163.0>@vmq_sysmon_handler:handle_event:95 monitor busy_dist_port <0.28189.38>  {#Port<0.240054>,unknown}\r\n2018-11-29 13:26:52.437 [info] <0.163.0>@vmq_sysmon_handler:handle_event:95 monitor busy_dist_port <0.5512.32>  {#Port<0.240054>,unknown}\r\n2018-11-29 13:27:04.524 [info] <0.163.0>@vmq_sysmon_handler:handle_event:95 monitor large_heap <0.232.0> [{name,plumtree_broadcast},{initial_call,{plumtree_broadcast,init,1}},{almost_current_function,{gen_server2,in,2}},{message_queue_len,58733}] [{old_heap_block_size,0},{heap_block_size,237288211},{mbuf_size,0},{stack_size,20},{old_heap_size,0},{heap_size,157902820}]\r\n2018-11-29 13:27:55.891 [info] <0.163.0>@vmq_sysmon_handler:handle_event:95 monitor large_heap <0.232.0> [{name,plumtree_broadcast},{initial_call,{plumtree_broadcast,init,1}},{almost_current_function,{gen_server2,drain,1}},{message_queue_len,1002}] [{old_heap_block_size,0},{heap_block_size,237288211},{mbuf_size,0},{stack_size,18},{old_heap_size,0},{heap_size,157287251}]\r\n2018-11-29 13:28:28.369 [warning] <0.232.0>@plumtree_broadcast:schedule_lazy_tick:697 Broadcast overloaded, 459580465ms mailbox traversal, schedule next lazy broadcast in 1464166ms, the min interval is 10000ms\r\n2018-11-29 13:28:31.862 [info] <0.163.0>@vmq_sysmon_handler:handle_event:95 monitor large_heap <0.232.0> [{name,plumtree_broadcast},{initial_call,{plumtree_broadcast,init,1}},{almost_current_function,{erlang,send,2}},{message_queue_len,2987}] [{old_heap_block_size,0},{heap_block_size,197740176},{mbuf_size,0},{stack_size,4305},{old_heap_size,0},{heap_size,160192315}]\r\n2018-11-29 13:28:34.401 [info] <0.163.0>@vmq_sysmon_handler:handle_event:95 monitor large_heap <0.232.0> [{name,plumtree_broadcast},{initial_call,{plumtree_broadcast,init,1}},{almost_current_function,{gen_server2,drain,1}},{message_queue_len,2754}] [{old_heap_block_size,0},{heap_block_size,164783480},{mbuf_size,0},{stack_size,20},{old_heap_size,0},{heap_size,160328783}]\r\n```\r\n(note that due to timezone offset, 13:00 in the log message corresponds to 14:00 in the charts)\r\n\r\nDespite the actual test ended before 15:10 (grafana time), the .118 node remained very busy for 1.5h.\r\n\r\nIn this particular instance of the problem, the .118 node eventually recovered from the crisis. However, we have seen situations where a VerneMQ was killed and, in consequence, another VerneMQ node crashed:\r\n\r\nx.y.z.118:\r\n```\r\n=erl_crash_dump:0.5\r\nFri Nov 23 14:58:03 2018\r\nSlogan: eheap_alloc: Cannot allocate 29247236448 bytes of memory (of type \"heap\").\r\nSystem version: Erlang/OTP 21 [erts-10.1] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:64] [hipe]\r\nCompiled: Fri Sep 28 12:44:50 2018\r\nTaints: bcrypt_nif,mzmetrics,eleveldb,crypto\r\nAtoms: 17648\r\nCalling Thread: scheduler:0 \r\n```\r\n\r\nx.y.z.95:\r\n```\r\n2018-11-23 14:58:03.125 [warning] <0.384.0>@vmq_cluster_mon:handle_info:122 cluster node 'vernemq@x.y.z.118' DOWN\r\n2018-11-23 14:58:03.143 [error] <0.209.0> Supervisor plumtree_sup had child plumtree_metadata_hashtree started with plumtree_metadata_hashtree:start_link() at <0.22939.11> exit with reason {{nodedown,'vernemq@x.y.z.118'},{gen_server,call,[{plumtree_metadata_manager,'vernemq@x.y.z.118'},{merge,{{vmq,subscriber},{[],<<\"mzbench-pub-96935\">>}},{metadata,{[{'vernemq@x.y.z.95',3,[]},{'vernemq@x.y.z.118',14,[{[{'vernemq@x.y.z.118',true,[{[<<\"qwe\">>,<<\"asd\">>,<<\"mzbench-pub-96935\">>],2}]}],{1542,982251,522645}}]},{'vernemq@x.y.z.204',3,[]},{'vernemq@x.y.z.144',6,[]}],[]}}},infinity]}} in context child_terminated\r\n2018-11-23 14:58:03.144 [error] <0.2938.18> gen_fsm <0.2938.18> in state exchange terminated with reason: {{{nodedown,'vernemq@x.y.z.118'},{gen_server,call,[{plumtree_metadata_manager,'vernemq@x.y.z.118'},{merge,{{vmq,subscriber},{[],<<\"mzbench-pub-96935\">>}},{metadata,{[{'vernemq@x.y.z.95',3,[]},{'vernemq@x.y.z.118',14,[{[{'vernemq@x.y.z.118',true,[{[<<\"qwe\">>,<<\"asd\">>,<<\"mzbench-pub-96935\">>],2}]}],{1542,982251,522645}}]},{'vernemq@x.y.z.204',3,[]},{'vernemq@159.69.220.144',6,[]}],[]}}},infinity]}},{gen_server,call,[plumtree_metadata_hashtree,{compare,#Fun<plumtree_m..>,...},...]}}\r\n2018-11-23 14:58:03.150 [error] <0.2938.18> CRASH REPORT Process <0.2938.18> with 0 neighbours exited with reason: {{{nodedown,'vernemq@x.y.z.118'},{gen_server,call,[{plumtree_metadata_manager,'vernemq@x.y.z.118'},{merge,{{vmq,subscriber},{[],<<\"mzbench-pub-96935\">>}},{metadata,{[{'vernemq@x.y.z.95',3,[]},{'vernemq@x.y.z.118',14,[{[{'vernemq@x.y.z.118',true,[{[<<\"qwe\">>,<<\"asd\">>,<<\"mzbench-pub-96935\">>],2}]}],{1542,982251,522645}}]},{'vernemq@x.y.z.204',3,[]},{'vernemq@x.y.z.144',6,[]}],[]}}},infinity]}},{gen_server,call,[plumtree_metadata_hashtree,{compare,#Fun<plumtree_m..>,...},...]}} in gen_fsm:terminate/7 line 609 \r\n```\r\n\r\nIt's worth mentioning that initially we have seen this problem erlang.distribution_buffer_size = 64MB and default values for plumtree.outstanding_limit and +hmqd. We started to experiment with those in order to mitigate the issue.\r\n\r\nIs it a known issue? Are there any recommended workarounds? The reason we tried changing erlang.distribution_buffer_size and plumtree.outstanding_limit was that we observed high traffic (even when the test ended). Do you think tweaking these parameters can help?"},"comment":{"url":"https://api.github.com/repos/vernemq/vernemq/issues/comments/448512061","html_url":"https://github.com/vernemq/vernemq/issues/988#issuecomment-448512061","issue_url":"https://api.github.com/repos/vernemq/vernemq/issues/988","id":448512061,"node_id":"MDEyOklzc3VlQ29tbWVudDQ0ODUxMjA2MQ==","user":{"login":"larshesel","id":679187,"node_id":"MDQ6VXNlcjY3OTE4Nw==","avatar_url":"https://avatars3.githubusercontent.com/u/679187?v=4","gravatar_id":"","url":"https://api.github.com/users/larshesel","html_url":"https://github.com/larshesel","followers_url":"https://api.github.com/users/larshesel/followers","following_url":"https://api.github.com/users/larshesel/following{/other_user}","gists_url":"https://api.github.com/users/larshesel/gists{/gist_id}","starred_url":"https://api.github.com/users/larshesel/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/larshesel/subscriptions","organizations_url":"https://api.github.com/users/larshesel/orgs","repos_url":"https://api.github.com/users/larshesel/repos","events_url":"https://api.github.com/users/larshesel/events{/privacy}","received_events_url":"https://api.github.com/users/larshesel/received_events","type":"User","site_admin":false},"created_at":"2018-12-19T08:35:40Z","updated_at":"2018-12-19T08:35:40Z","author_association":"CONTRIBUTOR","body":"hi @szymonk @p3we, we just merged both vernemq/plumtree#22 and erlio/gen_server2#1.\r\n\r\nWe're considering what the default value should be if we'd want it to be disabled by default or if we should enable it - and we're leaning towards enabling it - which value would you did you use in your tests? Would you like to do the PR for VerneMQ as well? "}}
{"actor":{"display_login":"larshesel"}}