{"action":"created","issue":{"url":"https://api.github.com/repos/scylladb/scylla/issues/1622","repository_url":"https://api.github.com/repos/scylladb/scylla","labels_url":"https://api.github.com/repos/scylladb/scylla/issues/1622/labels{/name}","comments_url":"https://api.github.com/repos/scylladb/scylla/issues/1622/comments","events_url":"https://api.github.com/repos/scylladb/scylla/issues/1622/events","html_url":"https://github.com/scylladb/scylla/issues/1622","id":173887967,"number":1622,"title":"[master] Scylla server/API server locking up with very large column sizes","user":{"login":"lmr","id":296807,"avatar_url":"https://avatars.githubusercontent.com/u/296807?v=3","gravatar_id":"","url":"https://api.github.com/users/lmr","html_url":"https://github.com/lmr","followers_url":"https://api.github.com/users/lmr/followers","following_url":"https://api.github.com/users/lmr/following{/other_user}","gists_url":"https://api.github.com/users/lmr/gists{/gist_id}","starred_url":"https://api.github.com/users/lmr/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/lmr/subscriptions","organizations_url":"https://api.github.com/users/lmr/orgs","repos_url":"https://api.github.com/users/lmr/repos","events_url":"https://api.github.com/users/lmr/events{/privacy}","received_events_url":"https://api.github.com/users/lmr/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/scylladb/scylla/labels/bug","name":"bug","color":"eb6420"}],"state":"open","locked":false,"assignee":{"login":"tgrabiec","id":283695,"avatar_url":"https://avatars.githubusercontent.com/u/283695?v=3","gravatar_id":"","url":"https://api.github.com/users/tgrabiec","html_url":"https://github.com/tgrabiec","followers_url":"https://api.github.com/users/tgrabiec/followers","following_url":"https://api.github.com/users/tgrabiec/following{/other_user}","gists_url":"https://api.github.com/users/tgrabiec/gists{/gist_id}","starred_url":"https://api.github.com/users/tgrabiec/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tgrabiec/subscriptions","organizations_url":"https://api.github.com/users/tgrabiec/orgs","repos_url":"https://api.github.com/users/tgrabiec/repos","events_url":"https://api.github.com/users/tgrabiec/events{/privacy}","received_events_url":"https://api.github.com/users/tgrabiec/received_events","type":"User","site_admin":false},"assignees":[{"login":"tgrabiec","id":283695,"avatar_url":"https://avatars.githubusercontent.com/u/283695?v=3","gravatar_id":"","url":"https://api.github.com/users/tgrabiec","html_url":"https://github.com/tgrabiec","followers_url":"https://api.github.com/users/tgrabiec/followers","following_url":"https://api.github.com/users/tgrabiec/following{/other_user}","gists_url":"https://api.github.com/users/tgrabiec/gists{/gist_id}","starred_url":"https://api.github.com/users/tgrabiec/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tgrabiec/subscriptions","organizations_url":"https://api.github.com/users/tgrabiec/orgs","repos_url":"https://api.github.com/users/tgrabiec/repos","events_url":"https://api.github.com/users/tgrabiec/events{/privacy}","received_events_url":"https://api.github.com/users/tgrabiec/received_events","type":"User","site_admin":false}],"milestone":{"url":"https://api.github.com/repos/scylladb/scylla/milestones/15","html_url":"https://github.com/scylladb/scylla/milestones/1.4","labels_url":"https://api.github.com/repos/scylladb/scylla/milestones/15/labels","id":1794297,"number":15,"title":"1.4","description":"","creator":{"login":"tzach","id":170200,"avatar_url":"https://avatars.githubusercontent.com/u/170200?v=3","gravatar_id":"","url":"https://api.github.com/users/tzach","html_url":"https://github.com/tzach","followers_url":"https://api.github.com/users/tzach/followers","following_url":"https://api.github.com/users/tzach/following{/other_user}","gists_url":"https://api.github.com/users/tzach/gists{/gist_id}","starred_url":"https://api.github.com/users/tzach/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tzach/subscriptions","organizations_url":"https://api.github.com/users/tzach/orgs","repos_url":"https://api.github.com/users/tzach/repos","events_url":"https://api.github.com/users/tzach/events{/privacy}","received_events_url":"https://api.github.com/users/tzach/received_events","type":"User","site_admin":false},"open_issues":40,"closed_issues":25,"state":"open","created_at":"2016-05-29T08:33:08Z","updated_at":"2016-09-21T11:03:55Z","due_on":"2016-09-30T00:00:00Z","closed_at":null},"comments":6,"created_at":"2016-08-29T22:27:36Z","updated_at":"2016-09-22T09:54:39Z","closed_at":null,"body":"Running the limits test on the latest master, we get the following error:\r\n\r\n    ======================================================================\r\n    ERROR: max_column_value_size_test (limits_test.TestLimits)\r\n    ----------------------------------------------------------------------\r\n    Traceback (most recent call last):\r\n      File \"/home/lmr/Code/scylla-dtest/limits_test.py\", line 134, in max_column_value_size_test\r\n        self._do_test_blob_size(session, node, size - 1)\r\n      File \"/home/lmr/Code/scylla-dtest/limits_test.py\", line 121, in _do_test_blob_size\r\n        session.execute(\"\"\"DROP TABLE test1\"\"\")\r\n      File \"cassandra/cluster.py\", line 1961, in cassandra.cluster.Session.execute (cassandra/cluster.c:34076)\r\n        return self.execute_async(query, parameters, trace, custom_payload, timeout, execution_profile).result()\r\n      File \"cassandra/cluster.py\", line 3649, in cassandra.cluster.ResponseFuture.result (cassandra/cluster.c:69755)\r\n        raise self._final_exception\r\n    NoHostAvailable: ('Unable to complete the operation against any hosts', {})\r\n    -------------------- >> begin captured logging << --------------------\r\n    dtest: DEBUG: cluster ccm directory: /home/lmr/.dtest/dtest-aWRxk_\r\n    cassandra.cluster: WARNING: Host 127.0.0.1 has been marked down\r\n    --------------------- >> end captured logging << ---------------------\r\n\r\n    ======================================================================\r\n    ERROR: max_column_value_size_test (limits_test.TestLimits)\r\n    ----------------------------------------------------------------------\r\n    Traceback (most recent call last):\r\n      File \"/home/lmr/Code/scylla-dtest/dtest.py\", line 596, in tearDown\r\n        raise AssertionError('Unexpected error in %s node log: %s' % (node.name, errors))\r\n    AssertionError: Unexpected error in node1 node log: ['ERROR 2016-08-29 17:45:04,540 [shard 0] storage_proxy - Exception when communicating with 127.0.0.1: std::bad_alloc']\r\n    -------------------- >> begin captured logging << --------------------\r\n    dtest: DEBUG: cluster ccm directory: /home/lmr/.dtest/dtest-aWRxk_\r\n    cassandra.cluster: WARNING: Host 127.0.0.1 has been marked down\r\n    dtest: DEBUG: removing ccm cluster test at: /home/lmr/.dtest/dtest-aWRxk_\r\n    dtest: DEBUG: clearing ssl stores from [/home/lmr/.dtest/dtest-aWRxk_] directory\r\n    dtest: DEBUG: force_clean called\r\n    --------------------- >> end captured logging << ---------------------\r\n\r\n    ----------------------------------------------------------------------\r\n    Ran 1 test in 158.944s\r\n\r\n    FAILED (errors=2)\r\n\r\nSo, what happens is that, by the time we try to drop the table created by the test, the server stops responding.\r\n\r\nCommit where the problem is showing up:\r\n\r\n    commit 809d739ae8e9a01e3a09a57acc1db6550619bc79\r\n    Author: Avi Kivity <avi@scylladb.com>\r\n    Date:   Mon Aug 29 13:26:04 2016 +0300\r\n\r\n        Merge seastar upstream\r\n        \r\n        * seastar 2b07b1f...0303e0c (3):\r\n          > scripts/posix_net_conf.sh: add support --cpu-mask mode\r\n          > file: improve tmpfs support\r\n          > file::close: remove trailing newline in log message\r\n\r\nSome major problems here:\r\n\r\n1) The bug is not 100% reproducible, some times the test will pass\r\n2) The node log mentions std::bad_alloc errors\r\n3) The symptoms appear to vary every time we have failures, one time we get 'NoHostAvailable: ('Unable to complete the operation against any hosts', {})',\r\n   other time we get errors from the nodetool command saying it couldn't communicate with the API server:\r\n\r\n     ======================================================================\r\n     ERROR: max_column_value_size_test (limits_test.TestLimits)\r\n     ----------------------------------------------------------------------\r\n     Traceback (most recent call last):\r\n       File \"/home/lmr/Code/scylla-dtest/limits_test.py\", line 134, in max_column_value_size_test\r\n         self._do_test_blob_size(session, node, size - 1)\r\n       File \"/home/lmr/Code/scylla-dtest/limits_test.py\", line 106, in _do_test_blob_size\r\n         node.flush()\r\n       File \"/home/lmr/Code/scylla-ccm/ccmlib/scylla_node.py\", line 784, in flush\r\n         self.nodetool(\"flush\")\r\n       File \"/home/lmr/Code/scylla-ccm/ccmlib/node.py\", line 693, in nodetool\r\n         raise NodetoolError(\" \".join(args), exit_status, stdout, stderr)\r\n     NodetoolError: Nodetool command '/home/lmr/Code/scylla/resources/cassandra/bin/nodetool -h localhost -p 7100 flush' failed; exit status: 2; stderr: error: Unable to connect to Scylla API server: java.net.ConnectException: Connection refused\r\n     -- StackTrace --\r\n     java.lang.IllegalStateException: Unable to connect to Scylla API server: java.net.ConnectException: Connection refused\r\n     \tat com.scylladb.jmx.api.APIClient.post(APIClient.java:116)\r\n     \tat org.apache.cassandra.service.StorageService.forceKeyspaceFlush(StorageService.java:645)\r\n     \tat sun.reflect.GeneratedMethodAccessor18.invoke(Unknown Source)\r\n     \tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\r\n     \tat java.lang.reflect.Method.invoke(Method.java:498)\r\n     \tat mx4j.server.ReflectionMBeanInvoker.invokeImpl(ReflectionMBeanInvoker.java:156)\r\n     \tat mx4j.server.ReflectionMBeanInvoker.doInvoke(ReflectionMBeanInvoker.java:117)\r\n     \tat mx4j.server.ReflectionMBeanInvoker.invoke(ReflectionMBeanInvoker.java:52)\r\n     \tat mx4j.server.interceptor.InvokerMBeanServerInterceptor.invoke(InvokerMBeanServerInterceptor.java:238)\r\n     \tat mx4j.server.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:120)\r\n     \tat mx4j.server.interceptor.SecurityMBeanServerInterceptor.invoke(SecurityMBeanServerInterceptor.java:84)\r\n     \tat mx4j.server.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:120)\r\n     \tat mx4j.server.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:120)\r\n     \tat mx4j.server.interceptor.ContextClassLoaderMBeanServerInterceptor.invoke(ContextClassLoaderMBeanServerInterceptor.java:203)\r\n     \tat mx4j.server.MX4JMBeanServer.invoke(MX4JMBeanServer.java:1043)\r\n     \tat mx4j.server.ChainedMBeanServer.invoke(ChainedMBeanServer.java:196)\r\n     \tat javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1468)\r\n     \tat javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:76)\r\n     \tat javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1309)\r\n     \tat javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1401)\r\n     \tat javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:829)\r\n     \tat sun.reflect.GeneratedMethodAccessor17.invoke(Unknown Source)\r\n     \tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\r\n     \tat java.lang.reflect.Method.invoke(Method.java:498)\r\n     \tat sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:324)\r\n     \tat sun.rmi.transport.Transport$1.run(Transport.java:200)\r\n     \tat sun.rmi.transport.Transport$1.run(Transport.java:197)\r\n     \tat java.security.AccessController.doPrivileged(Native Method)\r\n     \tat sun.rmi.transport.Transport.serviceCall(Transport.java:196)\r\n     \tat sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:568)\r\n     \tat sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826)\r\n     \tat sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:683)\r\n     \tat java.security.AccessController.doPrivileged(Native Method)\r\n     \tat sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)\r\n     \tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\r\n     \tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\r\n     \tat java.lang.Thread.run(Thread.java:745)\r\n\r\n\r\n     -------------------- >> begin captured logging << --------------------\r\n     dtest: DEBUG: cluster ccm directory: /home/lmr/.dtest/dtest-6ZPjXq\r\n     cassandra.cluster: WARNING: Host 127.0.0.1 has been marked down\r\n     cassandra.cluster: WARNING: [control connection] Error connecting to 127.0.0.1:\r\n     Traceback (most recent call last):\r\n       File \"cassandra/cluster.py\", line 2535, in cassandra.cluster.ControlConnection._reconnect_internal (cassandra/cluster.c:45414)\r\n         return self._try_connect(host)\r\n       File \"cassandra/cluster.py\", line 2557, in cassandra.cluster.ControlConnection._try_connect (cassandra/cluster.c:45931)\r\n         connection = self._cluster.connection_factory(host.address, is_control_connection=True)\r\n       File \"cassandra/cluster.py\", line 1107, in cassandra.cluster.Cluster.connection_factory (cassandra/cluster.c:14943)\r\n         return self.connection_class.factory(address, self.connect_timeout, *args, **kwargs)\r\n       File \"cassandra/connection.py\", line 327, in cassandra.connection.Connection.factory (cassandra/connection.c:5652)\r\n         raise conn.last_error\r\n     error: [Errno 104] Connection reset by peer\r\n     --------------------- >> end captured logging << ---------------------\r\n\r\n"},"comment":{"url":"https://api.github.com/repos/scylladb/scylla/issues/comments/248858406","html_url":"https://github.com/scylladb/scylla/issues/1622#issuecomment-248858406","issue_url":"https://api.github.com/repos/scylladb/scylla/issues/1622","id":248858406,"user":{"login":"gleb-cloudius","id":6554938,"avatar_url":"https://avatars.githubusercontent.com/u/6554938?v=3","gravatar_id":"","url":"https://api.github.com/users/gleb-cloudius","html_url":"https://github.com/gleb-cloudius","followers_url":"https://api.github.com/users/gleb-cloudius/followers","following_url":"https://api.github.com/users/gleb-cloudius/following{/other_user}","gists_url":"https://api.github.com/users/gleb-cloudius/gists{/gist_id}","starred_url":"https://api.github.com/users/gleb-cloudius/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gleb-cloudius/subscriptions","organizations_url":"https://api.github.com/users/gleb-cloudius/orgs","repos_url":"https://api.github.com/users/gleb-cloudius/repos","events_url":"https://api.github.com/users/gleb-cloudius/events{/privacy}","received_events_url":"https://api.github.com/users/gleb-cloudius/received_events","type":"User","site_admin":false},"created_at":"2016-09-22T09:54:39Z","updated_at":"2016-09-22T09:54:39Z","body":"On Thu, Sep 22, 2016 at 02:39:15AM -0700, Tomasz Grabiec wrote:\n> \n> ```diff\n> diff --git a/core/thread.hh b/core/thread.hh\n> index ecae6f3..68b7a79 100644\n> --- a/core/thread.hh\n> +++ b/core/thread.hh\n> @@ -140,6 +140,7 @@ class thread_context {\n>      static std::unique_ptr<char[]> make_stack();\n>  public:\n>      thread_context(thread_attributes attr, std::function<void ()> func);\n> +    ~thread_context();\n>      void switch_in();\n>      void switch_out();\n>      bool should_yield() const;\n> diff --git a/core/thread.cc b/core/thread.cc\n> index 21b0188..2bda283 100644\n> --- a/core/thread.cc\n> +++ b/core/thread.cc\n> @@ -38,6 +38,10 @@ thread_context::thread_context(thread_attributes attr, std::function<void ()> fu\n>      setup();\n>  }\n>  \n> +thread_context::~thread_context() {\n> +    assert(mprotect(_stack.get(), getpagesize(), PROT_READ | PROT_WRITE) == 0);\n> +}\n> +\n>  std::unique_ptr<char[]>\n>  thread_context::make_stack() {\n>      auto stack = std::make_unique<char[]>(_stack_size);\n> @@ -58,6 +62,7 @@ thread_context::setup() {\n>      auto main = reinterpret_cast<void (*)()>(&thread_context::s_main);\n>      auto r = getcontext(&initial_context);\n>      throw_system_error_on(r == -1);\n> +    assert(mprotect(_stack.get(), getpagesize(), PROT_READ) == 0);\n>      initial_context.uc_stack.ss_sp = _stack.get();\n>      initial_context.uc_stack.ss_size = _stack_size;\n>      initial_context.uc_link = nullptr;\n> \n> ```\n> \n\nThis effectively reduces stack size by 4K though. Probably does not\nmatter much in practice and some other call chain will eventually overflow.\n\n--\n\t\t\tGleb.\n"}}
{"actor":{"display_login":"gleb-cloudius"}}