Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-37087

Query is not timing out for long running queries

    XMLWordPrintable

Details

    Description

      Build: 6.5.0-4890

      Test:

      ./testrunner -i vikas-nodes.ini -t eventing.eventing_n1ql.EventingN1QL.test_n1ql_timeout,nodes_init=4,services_init=kv-eventing-index-n1ql,dataset=default,groups=simple,reset_services=True,skip_cleanup=True 

      • Deploy handler with long running query 

      function OnUpdate(doc, meta) {
          log('docId', meta.id);
          try{
          var i=0;
          var query = SELECT * From `travel-sample`;
          for(var q of query){
              dst_bucket[i] = q;
              i++;
          }
          query.close();
          }
          catch(e){
              log(e);
          }
      }
      function OnDelete(meta) {
          log('docId', meta.id);
          try{
          var i=0;
          var query = SELECT * From `travel-sample`;
          for(var q of query){
              delete dst_bucket[i];
              i++;
          }
          query.close();
          }
          catch(e){
              log(e);
          }
      }
      
      

      * Handler timeout is 10 sec . query timing is ~16sec

      • Seeing handler timeout instead of query timeout

       [
          {
              "dcp_feed_boundary": "from_now",
              "event_processing_stats": {
                  "adhoc_timer_response_received": 1,
                  "agg_messages_sent_to_worker": 32651,
                  "agg_queue_memory": 0,
                  "agg_queue_memory_cap": 267386880,
                  "agg_queue_size": 0,
                  "agg_queue_size_cap": 300000,
                  "agg_timer_feedback_queue_cap": 1500,
                  "dcp_mutation": 1,
                  "dcp_mutation_sent_to_worker": 1,
                  "dcp_snapshot": 1,
                  "dcp_stream_req_counter": 1024,
                  "dcp_streamreq": 1024,
                  "execution_stats": 6321,
                  "failure_stats": 6321,
                  "latency_stats": 6321,
                  "lcb_exception_stats": 6321,
                  "log_level": 3,
                  "num_processed_events": 1,
                  "processed_events_size": 240,
                  "thr_count": 3,
                  "thr_map": 3,
                  "v8_init": 3,
                  "v8_load": 3
              },
              "events_remaining": {
                  "dcp_backlog": 0
              },
              "execution_stats": {
                  "agg_queue_memory": 0,
                  "agg_queue_size": 0,
                  "curl": {
                      "delete": 0,
                      "get": 0,
                      "head": 0,
                      "post": 0,
                      "put": 0
                  },
                  "dcp_delete_msg_counter": 0,
                  "dcp_delete_parse_failure": 0,
                  "dcp_mutation_msg_counter": 1,
                  "dcp_mutation_parse_failure": 0,
                  "enqueued_dcp_delete_msg_counter": 0,
                  "enqueued_dcp_mutation_msg_counter": 1,
                  "enqueued_timer_msg_counter": 0,
                  "feedback_queue_size": 0,
                  "filtered_dcp_delete_counter": 0,
                  "filtered_dcp_mutation_counter": 0,
                  "lcb_retry_failure": 0,
                  "messages_parsed": 32639,
                  "num_processed_events": 1,
                  "on_delete_failure": 0,
                  "on_delete_success": 0,
                  "on_update_failure": 0,
                  "on_update_success": 1,
                  "processed_events_size": 240,
                  "timer_create_counter": 0,
                  "timer_create_failure": 0,
                  "timer_msg_counter": 0,
                  "timer_responses_sent": 0,
                  "timestamp": {
                      "19926": "2019-11-28T11:10:58Z",
                      "19931": "2019-11-28T11:10:58Z",
                      "19933": "2019-11-28T11:10:58Z"
                  },
                  "uv_msg_parse_failure": 0,
                  "uv_try_write_failure_counter": 0
              },
              "failure_stats": {
                  "app_worker_setting_events_lost": 0,
                  "bucket_op_exception_count": 0,
                  "checkpoint_failure_count": 0,
                  "curl_non_200_response": 0,
                  "dcp_events_lost": 0,
                  "debugger_events_lost": 0,
                  "delete_events_lost": 0,
                  "mutation_events_lost": 0,
                  "n1ql_op_exception_count": 0,
                  "timeout_count": 1,
                  "timer_callback_missing_counter": 0,
                  "timer_context_size_exceeded_counter": 0,
                  "timer_events_lost": 0,
                  "timestamp": {
                      "19926": "2019-11-28T11:10:58Z",
                      "19931": "2019-11-28T11:10:58Z",
                      "19933": "2019-11-28T11:10:58Z"
                  },
                  "v8worker_events_lost": 0
              },
              "function_name": "Function_847162565_test_n1ql_timeout",
              "gocb_creds_request_counter": 8,
              "function_id": 2323974959,
              "internal_vb_distribution_stats": {
                  "worker_Function_847162565_test_n1ql_timeout_0": "[0-341]",
                  "worker_Function_847162565_test_n1ql_timeout_1": "[342-682]",
                  "worker_Function_847162565_test_n1ql_timeout_2": "[683-1023]"
              },
              "latency_percentile_stats": {
                  "100": 9999900,
                  "50": 9999900,
                  "80": 9999900,
                  "90": 9999900,
                  "95": 9999900,
                  "99": 9999900
              },
              "lcb_creds_request_counter": 20,
              "lcb_exception_stats": {},
              "planner_stats": [
                  {
                      "host_name": "10.143.192.102:8096",
                      "start_vb": 0,
                      "vb_count": 1024
                  }
              ],
              "metastore_stats": {},
              "vb_distribution_stats_from_metadata": {
                  "10.143.192.102:8096": {
                      "worker_Function_847162565_test_n1ql_timeout_0": "[0-341]",
                      "worker_Function_847162565_test_n1ql_timeout_1": "[342-682]",
                      "worker_Function_847162565_test_n1ql_timeout_2": "[683-1023]"
                  }
              },
              "worker_pids": {
                  "worker_Function_847162565_test_n1ql_timeout_0": 19926,
                  "worker_Function_847162565_test_n1ql_timeout_1": 19931,
                  "worker_Function_847162565_test_n1ql_timeout_2": 19933
              }
          }
      ]

      Attachments

        1. 172.23.104.103-20191128-1141-diag.zip
          38.19 MB
        2. 172.23.104.105-20191128-1142-diag.zip
          9.32 MB
        3. 172.23.104.107-20191128-1144-diag.zip
          6.87 MB
        4. test_17 (1).zip
          47.70 MB
        5. test.log
          57 kB

        Issue Links

          For Gerrit Dashboard: MB-37087
          # Subject Branch Project Status CR V

          Activity

            People

              siri Sriram Melkote (Inactive)
              vikas.chaudhary Vikas Chaudhary
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes

                  PagerDuty