Query Debugging

You can debug a specific query at the query level by adding the <trace> keyword before the query string that you want to debug.

Here is an example:

<trace> select * from /exampleRegion

You can also write:

<TRACE> select * from /exampleRegion

Before the query is executed and once it completes, Tanzu GemFire will log messages in $GEMFIRE_DIR/system.log with the following information:

[info 2011/08/29 11:24:35.462 PDT CqServer <main> tid=0x1] Starting query: select * from /exampleRegion

[info 2011/08/29 11:24:35.472 PDT CqServer <main> tid=0x1] Query Executed in 9.619656 ms; rowCount = 99; indexesUsed(0) "select * from /exampleRegion"

If you want to enable debugging for all queries, you can enable query execution logging by setting a System property on the command line during start-up:

gfsh>start server --name=server_name -–J=-Dgemfire.Query.VERBOSE=true

Or you can set the property programmatically:

System.setProperty("gemfire.Query.VERBOSE","true");

As an example, let us say you have an EmployeeRegion that that contains Employee objects as values and the objects have public fields in them like ID and status.

Employee.java
Class Employee {
 public int ID;
 public String status;
 - - - - - -
 - - - - - -
}

In addition, you have created the following indexes for the region:

<index name="sampleIndex-1">
<functional from-clause="/test " expression="ID"/>
</index>
<index name="sampleIndex-2">
<functional from-clause="/test " expression="status"/>
</index>

After you have set gemfire.Query.VERBOSE to “true”, you could see the following debug messages in the logs after running queries on the EmployeeRegion or its indexes:

• If indexes are not used in the query execution, you would see a debug message like this:

  [info 2011/08/29 11:24:35.472 PDT CqServer <main> tid=0x1] Query Executed in 9.619656 ms; rowCount = 99; indexesUsed(0) "select * from /test k where ID > 0 and status='active'"
  

• When single index is used in query execution, you might see a debug message like this:

  [info 2011/08/29 11:24:35.472 PDT CqServer <main> tid=0x1] Query Executed in 101.43499 ms; rowCount = 199; indexesUsed(1):sampleIndex-1(Results: 199) "select count *   from /test k where ID > 0"
  

• When multiple indexes are used by a query, you might see a debug message like this:

  [info 2011/08/29 11:24:35.472 PDT CqServer <main> tid=0x1] Query Executed in 79.43847 ms; rowCount = 199; indexesUsed(2):sampleIndex-2(Results: 100),sampleIndex-1(Results: 199) "select * from /test k where ID > 0 OR status='active'"
  

In above log messages, the following information is provided:

• “rowCount” represents ResultSet size for the query.
• "indexesUsed(\n) " shows n indexes were used for finding the results of the query.
• Each index name and its corresponding results are reported respectively.
• The log can be identified with the original query string itself appended in the end.