added "bindVars" to attributes of currently running and slow queries

CHANGELOG

@@ -1,6 +1,8 @@
 devel
 -----
 
+* added "bindVars" to attributes of currently running and slow queries
+
 * added input file type `auto` for arangoimp so it can automatically detect the 
   type of the input file from the filename extension
 

Documentation/DocuBlocks/Rest/AQL/GetApiQueryCurrent.md

@@ -12,11 +12,15 @@ database. Each query is a JSON object with the following attributes:
 
 - *query*: the query string (potentially truncated)
 
+- *bindVars*: the bind parameter values used by the query
+
 - *started*: the date and time when the query was started
 
 - *runTime*: the query's run time up to the point the list of queries was
   queried
 
+- *state*: the query's current execution state (as a string)
+
 @RESTRETURNCODES
 
 @RESTRETURNCODE{200}

Documentation/DocuBlocks/Rest/AQL/GetApiQuerySlow.md

@@ -5,8 +5,8 @@
 @RESTHEADER{GET /_api/query/slow, Returns the list of slow AQL queries}
 
 @RESTDESCRIPTION
-Returns an array containing the last AQL queries that exceeded the slow
+Returns an array containing the last AQL queries that are finished and
-query threshold in the selected database.
+have exceeded the slow query threshold in the selected database.
 The maximum amount of queries in the list can be controlled by setting
 the query tracking property `maxSlowQueries`. The threshold for treating
 a query as *slow* can be adjusted by setting the query tracking property
@@ -18,10 +18,14 @@ Each query is a JSON object with the following attributes:
 
 - *query*: the query string (potentially truncated)
 
+- *bindVars*: the bind parameter values used by the query
+
 - *started*: the date and time when the query was started
 
-- *runTime*: the query's run time up to the point the list of queries was
+- *runTime*: the query's total run time 
-  queried
+
+- *state*: the query's current execution state (will always be "finished"
+  for the list of slow queries)
 
 @RESTRETURNCODES
 

UnitTests/HttpInterface/api-query-analysis-spec-timecritical.rb

@@ -18,6 +18,8 @@ describe ArangoDB do
     @fastQueryBody = JSON.dump({query: @fastQuery})
     @longQuery = "FOR x IN 1..1 LET y = SLEEP(0.2) LET a = y LET b = a LET c = b LET d = c LET e = d LET f = e  RETURN x"
     @longQueryBody = JSON.dump({query: @longQuery})
+    @queryWithBind = "FOR x IN 1..5 LET y = SLEEP(@value) RETURN x"
+    @queryWithBindBody = JSON.dump({query: @queryWithBind, bindVars: {value: 2}})
     @queryEndpoint ="/_api/cursor"
     @queryPrefix = "api-cursor"
   end
@@ -33,20 +35,24 @@ describe ArangoDB do
       ArangoDB.log_post(@queryPrefix, @queryEndpoint, :body => @fastQueryBody, :headers => {"X-Arango-Async" => async })
     end
   end
-
+  
+  def send_queries_with_bind (count = 1, async = "true") 
+    count.times do
+      ArangoDB.log_post(@queryPrefix, @queryEndpoint, :body => @queryWithBindBody, :headers => {"X-Arango-Async" => async })
+    end
+  end
 
   def contains_query (body, testq = @query)
-      found = false
       res = JSON.parse body
       res.each do |q|
         if q["query"] === testq
-          found = true
+          return q
         end
       end
-      return found
+      return false
   end
 
-  it "should activate Tracking" do
+  it "should activate tracking" do
     doc = ArangoDB.log_put("#{@prefix}-properties", @properties, :body => JSON.dump({enable: true}))
     doc.code.should eq(200)
   end
@@ -79,7 +85,35 @@ describe ArangoDB do
       doc = ArangoDB.log_get("#{@prefix}-current", @current)
       doc.code.should eq(200)
       found = contains_query doc.body, @query
-      found.should eq(true)
+      found.should_not eq(false)
+      found.should have_key("id")
+      found["id"].should match(/^\d+$/)
+      found.should have_key("query")
+      found["query"].should eq(@query)
+      found.should have_key("bindVars")
+      found["bindVars"].should eq({})
+      found.should have_key("runTime")
+      found["runTime"].should be_kind_of(Numeric)
+      found.should have_key("started")
+      found["state"].should eq("executing");
+    end
+    
+    it "should track running queries, with bind parameters" do
+      send_queries_with_bind
+      doc = ArangoDB.log_get("#{@prefix}-current-bind", @current)
+      doc.code.should eq(200)
+      found = contains_query doc.body, @queryWithBind
+      found.should_not eq(false)
+      found.should have_key("id")
+      found["id"].should match(/^\d+$/)
+      found.should have_key("query")
+      found["query"].should eq(@queryWithBind)
+      found.should have_key("bindVars")
+      found["bindVars"].should eq({"value" => 2})
+      found.should have_key("runTime")
+      found["runTime"].should be_kind_of(Numeric)
+      found.should have_key("started")
+      found["state"].should eq("executing")
     end
 
     it "should track slow queries by threshold" do
@@ -99,7 +133,14 @@ describe ArangoDB do
       doc = ArangoDB.log_get("#{@prefix}-slow", @slow)
       doc.code.should eq(200)
       found = contains_query doc.body, @fastQuery
-      found.should eq(true)
+      found.should_not eq(false)
+      found.should have_key("query")
+      found["query"].should eq(@fastQuery)
+      found["bindVars"].should eq({})
+      found.should have_key("runTime")
+      found["runTime"].should be_kind_of(Numeric)
+      found.should have_key("started")
+      found["state"].should eq("finished")
     end
 
     it "should track at most n slow queries" do 
@@ -143,9 +184,12 @@ describe ArangoDB do
       res = JSON.parse doc.body
       res.length.should eq(1)
       # This string is exactly 64 bytes long
-      shortend = "FOR x IN 1..1 LET y = SLEEP(0.2) LET a = y LET b = a LET c = b L"
+      shortened = "FOR x IN 1..1 LET y = SLEEP(0.2) LET a = y LET b = a LET c = b L"
-      found = contains_query doc.body, shortend + "..."
+      found = contains_query doc.body, shortened + "..."
-      found.should eq(true)
+      found.should_not eq(false)
+      found.should have_key("query")
+      found["query"].should eq(shortened + "...")
+      found["bindVars"].should eq({})
     end
 
     it "should properly truncate UTF8 symbols" do
@@ -156,9 +200,12 @@ describe ArangoDB do
       res = JSON.parse doc.body
       res.length.should eq(1)
       # This string is exactly 64 bytes long
-      shortend = "FOR x IN 1..1 LET y = SLEEP(0.2) LET a= y LET b= a LET c= \"öö"
+      shortened = "FOR x IN 1..1 LET y = SLEEP(0.2) LET a= y LET b= a LET c= \"öö"
-      found = contains_query doc.body, shortend + "..."
+      found = contains_query doc.body, shortened + "..."
-      found.should eq(true)
+      found.should_not eq(false)
+      found.should have_key("query")
+      found["query"].should eq(shortened + "...")
+      found["bindVars"].should eq({})
     end
 
     it "should be able to kill a running query" do

arangod/Aql/BindParameters.h

@@ -57,6 +57,9 @@ class BindParameters {
     return _parameters;
   }
 
+  /// @brief return the bind parameters as passed by the user
+  std::shared_ptr<arangodb::velocypack::Builder> builder() const { return _builder; }
+
   /// @brief create a hash value for the bind parameters
   uint64_t hash() const;
 

arangod/Aql/Query.h

@@ -298,6 +298,11 @@ class Query {
   /// @brief look up a graph in the _graphs collection
   Graph const* lookupGraphByName(std::string const& name);
 
+  /// @brief return the bind parameters as passed by the user
+  std::shared_ptr<arangodb::velocypack::Builder> bindParameters() const { 
+    return _bindParameters.builder(); 
+  }
+
  private:
   /// @brief initializes the query
   void init();

arangod/Aql/QueryList.cpp

@@ -33,10 +33,12 @@
 using namespace arangodb::aql;
 
 QueryEntryCopy::QueryEntryCopy(TRI_voc_tick_t id,
-                               std::string&& queryString, double started,
+                               std::string&& queryString, 
+                               std::shared_ptr<arangodb::velocypack::Builder> bindParameters,
+                               double started,
                                double runTime, QueryExecutionState::ValueType state)
-    : id(id), queryString(std::move(queryString)), started(started), runTime(runTime),
+    : id(id), queryString(std::move(queryString)), bindParameters(bindParameters), 
-      state(state) {}
+      started(started), runTime(runTime), state(state) {}
 
 double const QueryList::DefaultSlowQueryThreshold = 10.0;
 size_t const QueryList::DefaultMaxSlowQueries = 64;
@@ -56,14 +58,6 @@ QueryList::QueryList(TRI_vocbase_t*)
   _current.reserve(64);
 }
 
-/// @brief destroy a query list
-QueryList::~QueryList() {
-  WRITE_LOCKER(writeLocker, _lock);
-
-  _current.clear();
-  _slow.clear();
-}
-
 /// @brief insert a query
 bool QueryList::insert(Query const* query) {
   // not enable or no query string
@@ -132,6 +126,7 @@ void QueryList::remove(Query const* query) {
         _slow.emplace_back(QueryEntryCopy(
             query->id(),
             std::move(q),
+            query->bindParameters(),
             started, now - started,
             QueryExecutionState::ValueType::FINISHED));
 
@@ -212,6 +207,7 @@ std::vector<QueryEntryCopy> QueryList::listCurrent() {
       result.emplace_back(
           QueryEntryCopy(query->id(),
                          extractQueryString(query, maxLength),
+                         query->bindParameters(),
                          started, now - started,
                          query->state()));
     }
@@ -227,7 +223,9 @@ std::vector<QueryEntryCopy> QueryList::listSlow() {
   {
     READ_LOCKER(readLocker, _lock);
     result.reserve(_slow.size());
-    result.assign(_slow.begin(), _slow.end());
+    for (auto const& it : _slow) {
+      result.emplace_back(it);
+    }
   }
 
   return result;

arangod/Aql/QueryList.h

@@ -34,26 +34,28 @@
 struct TRI_vocbase_t;
 
 namespace arangodb {
+namespace velocypack {
+class Builder;
+}
+
 namespace aql {
 
 class Query;
 
-// -----------------------------------------------------------------------------
-// --SECTION--                                                 struct QueryEntry
-// -----------------------------------------------------------------------------
-      
 struct QueryEntryCopy {
   QueryEntryCopy (TRI_voc_tick_t id,
                   std::string&& queryString,
+                  std::shared_ptr<arangodb::velocypack::Builder> bindParameters,
                   double started,
                   double runTime,
                   QueryExecutionState::ValueType state);
 
-  TRI_voc_tick_t  id;
+  TRI_voc_tick_t const id;
-  std::string     queryString;
+  std::string const queryString;
-  double          started;
+  std::shared_ptr<arangodb::velocypack::Builder> const bindParameters;
-  double          runTime;
+  double const started;
-  QueryExecutionState::ValueType state;
+  double const runTime;
+  QueryExecutionState::ValueType const state;
 };
 
 class QueryList {
@@ -62,7 +64,7 @@ class QueryList {
   explicit QueryList(TRI_vocbase_t*);
 
   /// @brief destroy a query list
-  ~QueryList();
+  ~QueryList() = default;
 
  public:
   /// @brief whether or not queries are tracked

arangod/RestHandler/RestQueryHandler.cpp

@@ -111,6 +111,11 @@ bool RestQueryHandler::readQuery(bool slow) {
     result.add(VPackValue(VPackValueType::Object));
     result.add("id", VPackValue(StringUtils::itoa(q.id)));
     result.add("query", VPackValue(q.queryString));
+    if (q.bindParameters != nullptr) {
+      result.add("bindVars", q.bindParameters->slice());
+    } else {
+      result.add("bindVars", arangodb::basics::VelocyPackHelper::EmptyObjectValue());
+    }
     result.add("started", VPackValue(timeString));
     result.add("runTime", VPackValue(q.runTime));
     result.add("state", VPackValue(QueryExecutionState::toString(q.state)));

arangod/V8Server/v8-vocbase.cpp

@@ -1099,12 +1099,12 @@ static void JS_ExplainAql(v8::FunctionCallbackInfo<v8::Value> const& args) {
 
   if (args.Length() < 1 || args.Length() > 3) {
     TRI_V8_THROW_EXCEPTION_USAGE(
-        "AQL_EXPLAIN(<querystring>, <bindvalues>, <options>)");
+        "AQL_EXPLAIN(<queryString>, <bindVars>, <options>)");
   }
 
   // get the query string
   if (!args[0]->IsString()) {
-    TRI_V8_THROW_TYPE_ERROR("expecting string for <querystring>");
+    TRI_V8_THROW_TYPE_ERROR("expecting string for <queryString>");
   }
 
   std::string const queryString(TRI_ObjectToString(args[0]));
@@ -1114,7 +1114,7 @@ static void JS_ExplainAql(v8::FunctionCallbackInfo<v8::Value> const& args) {
 
   if (args.Length() > 1) {
     if (!args[1]->IsUndefined() && !args[1]->IsNull() && !args[1]->IsObject()) {
-      TRI_V8_THROW_TYPE_ERROR("expecting object for <bindvalues>");
+      TRI_V8_THROW_TYPE_ERROR("expecting object for <bindVars>");
     }
     if (args[1]->IsObject()) {
       bindVars.reset(new VPackBuilder);
@@ -1285,12 +1285,12 @@ static void JS_ExecuteAql(v8::FunctionCallbackInfo<v8::Value> const& args) {
 
   if (args.Length() < 1 || args.Length() > 3) {
     TRI_V8_THROW_EXCEPTION_USAGE(
-        "AQL_EXECUTE(<querystring>, <bindvalues>, <options>)");
+        "AQL_EXECUTE(<queryString>, <bindVars>, <options>)");
   }
 
   // get the query string
   if (!args[0]->IsString()) {
-    TRI_V8_THROW_TYPE_ERROR("expecting string for <querystring>");
+    TRI_V8_THROW_TYPE_ERROR("expecting string for <queryString>");
   }
 
   std::string const queryString(TRI_ObjectToString(args[0]));
@@ -1303,7 +1303,7 @@ static void JS_ExecuteAql(v8::FunctionCallbackInfo<v8::Value> const& args) {
 
   if (args.Length() > 1) {
     if (!args[1]->IsUndefined() && !args[1]->IsNull() && !args[1]->IsObject()) {
-      TRI_V8_THROW_TYPE_ERROR("expecting object for <bindvalues>");
+      TRI_V8_THROW_TYPE_ERROR("expecting object for <bindVars>");
     }
     if (args[1]->IsObject()) {
       bindVars.reset(new VPackBuilder);
@@ -1481,6 +1481,11 @@ static void JS_QueriesCurrentAql(
       v8::Handle<v8::Object> obj = v8::Object::New(isolate);
       obj->Set(TRI_V8_ASCII_STRING("id"), V8TickId(isolate, q.id));
       obj->Set(TRI_V8_ASCII_STRING("query"), TRI_V8_STD_STRING(q.queryString));
+      if (q.bindParameters != nullptr) {
+        obj->Set(TRI_V8_ASCII_STRING("bindVars"), TRI_VPackToV8(isolate, q.bindParameters->slice()));
+      } else {
+        obj->Set(TRI_V8_ASCII_STRING("started"), v8::Object::New(isolate));
+      }
       obj->Set(TRI_V8_ASCII_STRING("started"), TRI_V8_STD_STRING(timeString));
       obj->Set(TRI_V8_ASCII_STRING("runTime"),
                v8::Number::New(isolate, q.runTime));
@@ -1533,6 +1538,7 @@ static void JS_QueriesSlowAql(v8::FunctionCallbackInfo<v8::Value> const& args) {
       v8::Handle<v8::Object> obj = v8::Object::New(isolate);
       obj->Set(TRI_V8_ASCII_STRING("id"), V8TickId(isolate, q.id));
       obj->Set(TRI_V8_ASCII_STRING("query"), TRI_V8_STD_STRING(q.queryString));
+      obj->Set(TRI_V8_ASCII_STRING("bindVars"), TRI_VPackToV8(isolate, q.bindParameters->slice()));
       obj->Set(TRI_V8_ASCII_STRING("started"), TRI_V8_STD_STRING(timeString));
       obj->Set(TRI_V8_ASCII_STRING("runTime"),
                v8::Number::New(isolate, q.runTime));

js/common/tests/shell/shell-query-timecritical-spec.js

@@ -125,6 +125,19 @@ describe('AQL query analyzer', function () {
       sendQuery(1, true);
       expect(testee.current().filter(filterQueries).length).to.equal(1);
     });
+    
+    it('should have proper running query descriptions', function () {
+      sendQuery(1, true);
+      let queries = testee.current().filter(filterQueries);
+      expect(queries.length).to.equal(1);
+      expect(queries[0]).to.have.property('id');
+      expect(queries[0]).to.have.property('query', query);
+      expect(queries[0]).to.have.property('bindVars');
+      expect(queries[0].bindVars).to.eql({});
+      expect(queries[0]).to.have.property('started');
+      expect(queries[0]).to.have.property('runTime');
+      expect(queries[0]).to.have.property('state', 'executing');
+    });
 
     it('should not track queries if turned off', function () {
       testee.properties({
@@ -165,7 +178,15 @@ describe('AQL query analyzer', function () {
 
       sendQuery(1, false);
       expect(testee.current().filter(filterQueries).length).to.equal(0);
-      expect(testee.slow().filter(filterQueries).length).to.equal(1);
+      let queries = testee.slow().filter(filterQueries);
+      expect(queries.length).to.equal(1);
+      expect(queries[0]).to.have.property('id');
+      expect(queries[0]).to.have.property('query', query);
+      expect(queries[0]).to.have.property('bindVars');
+      expect(queries[0].bindVars).to.eql({});
+      expect(queries[0]).to.have.property('started');
+      expect(queries[0]).to.have.property('runTime');
+      expect(queries[0]).to.have.property('state', 'finished');
     });
 
     it('should be able to clear the list of slow queries', function () {