Teiid 8.4 performance degrading with multiple concurrent requests

[anilallewar]

We are trying to perform load testing against a VDB going to a SQL Server by generating 40 concurrent requests. The table has about 768075 rows and we are just trying to read the first 1000 (data about .5 MB) by sending concurrent read requests to Teiid using/eclipse-open:☂=DSDSClient/C:\/Program Files\/Java\/jre6\/lib\/rt.jar<java.util.concurrent(ExecutorService.class☃ExecutorServicejava.util.concurrent.ExecutorService by running Runnable workers.

What we observed is that the query response time increases linearly based on the number of requests with the first clocking around seconds to the 40th one clocking 219 seconds. I have tried moving the memory off the heap and specifying the buffer manager settings but that didn't improve the performance. If I instead use the SQL driver to go against the database directly by creating 1 connection per thread, all the 40 requests complete max by 2 seconds.

Here are the memory settings

"JAVA_OPTS=-Xms1024M -Xmx4096M -XX:MaxPermSize=512M -XX:MaxDirectMemorySize=8G"

and the Buffer manager settings

<buffer-service use-disk="true"
  processor-batch-size="256" memory-buffer-off-heap="true" />

The results from the test

The time taken to run the query for iteration [18] is [40] seconds
The time taken to run the query for iteration [22] is [44] seconds
The time taken to run the query for iteration [34] is [52] seconds
The time taken to run the query for iteration [28] is [63] seconds
The time taken to run the query for iteration [32] is [64] seconds
The time taken to run the query for iteration [12] is [64] seconds
The time taken to run the query for iteration [11] is [67] seconds
The time taken to run the query for iteration [23] is [67] seconds
The time taken to run the query for iteration [10] is [69] seconds
The time taken to run the query for iteration [33] is [70] seconds
The time taken to run the query for iteration [5] is [90] seconds
The time taken to run the query for iteration [25] is [99] seconds
The time taken to run the query for iteration [8] is [100] seconds
The time taken to run the query for iteration [13] is [107] seconds
The time taken to run the query for iteration [35] is [107] seconds
The time taken to run the query for iteration [26] is [114] seconds
The time taken to run the query for iteration [38] is [118] seconds
The time taken to run the query for iteration [7] is [121] seconds
The time taken to run the query for iteration [4] is [122] seconds
The time taken to run the query for iteration [30] is [125] seconds
The time taken to run the query for iteration [17] is [127] seconds
The time taken to run the query for iteration [9] is [148] seconds
The time taken to run the query for iteration [16] is [154] seconds
The time taken to run the query for iteration [37] is [162] seconds
The time taken to run the query for iteration [14] is [167] seconds
The time taken to run the query for iteration [2] is [174] seconds
The time taken to run the query for iteration [15] is [178] seconds
The time taken to run the query for iteration [6] is [180] seconds
The time taken to run the query for iteration [27] is [181] seconds
The time taken to run the query for iteration [1] is [187] seconds
The time taken to run the query for iteration [39] is [187] seconds
The time taken to run the query for iteration [3] is [192] seconds
The time taken to run the query for iteration [31] is [193] seconds
The time taken to run the query for iteration [29] is [195] seconds
The time taken to run the query for iteration [40] is [201] seconds
The time taken to run the query for iteration [20] is [201] seconds
The time taken to run the query for iteration [19] is [209] seconds
The time taken to run the query for iteration [36] is [216] seconds
The time taken to run the query for iteration [24] is [217] seconds
The time taken to run the query for iteration [21] is [219] seconds

Snapshot of runtime resources used by Teiid

Metric	Actual
Session Count:	2
Memory in Use(KB):	0
Memory Used By Active Plans(KB):	-28472
Buffer Disk Reads:	640
Buffer Disk Writes:	118920
Buffer Cache Reads:	640
Buffer Cache Writes:	119811
Disk Space In Use(MB):	1336
Active Plan Count:	1
Waiting Plan Count:	0

What I noticed was that there were connection close exceptions on the server but the query ran fine.

16:38:29,424 ERROR [org.teiid.TRANSPORT] (New I/O worker #2) Unhandled exception
, closing client instance: java.io.IOException: An existing connection was forci
bly closed by the remote host

I also tried setting the buffer manager settings specifically as below.

<subsystem xmlns="urn:jboss:domain:teiid:1.0">
            <async-thread-pool>teiid-async</async-thread-pool>
            <max-threads>150</max-threads>
            <max-active-plans>20</max-active-plans>
            <!--
            1. Set the buffer manager to use disk.
            2. Reduce the processor-batch-size(number of records in a batch) processed by the teiid buffer manager
            from 512 to 256
            3. Set the max-processing-kb (The approximate amount of buffer memory in kilobytes allowable for a
            single processing operation (sort, grouping, etc.) regardless of existing memory commitments)
            to be 2GB
            4. Set the max-reserve-kb (The approximate amount of memory in kilobytes allowed to be held by the buffer manager)
            to be 4 GB
            5. Set the max-storage-object-size(maximum size of a buffered managed object in bytes and represents the individual batch page size)
            to 64 MB (64*1024*1024)
            6. Set the memory-buffer-space (Memory buffer space used by the buffer manager in MB) to be 6GB. Need to find out how this is
            different from max-reserve-kb
            7. Set the memory-buffer-off-heap (Set to true to hold the memory buffer off-heap. If true you must ensure that the VM can
            allocate that much direct memory) to "true"
             -->
            <buffer-service use-disk="true"
  processor-batch-size="256" max-processing-kb="2097152" max-reserve-kb="4194304"
  max-storage-object-size="67108864" memory-buffer-space="6144"
  memory-buffer-off-heap="true" />

But that gave exceptions for the buffer manager of nature as below

org.teiid.jdbc.TeiidSQLException: Batch not found in storage 4537

       at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135)
       at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71)
       at org.teiid.jdbc.StatementImpl.postReceiveResults(StatementImpl.java:667)
       at org.teiid.jdbc.StatementImpl.access$100(StatementImpl.java:63)
       at org.teiid.jdbc.StatementImpl$2.onCompletion(StatementImpl.java:516)
       at org.teiid.client.util.ResultsFuture.done(ResultsFuture.java:130)
       at org.teiid.client.util.ResultsFuture.access$200(ResultsFuture.java:37)
       at org.teiid.client.util.ResultsFuture$1.receiveResults(ResultsFuture.java:75)
       at org.teiid.net.socket.SocketServerInstanceImpl.receivedMessage(SocketServerInstanceImpl.java:235)
       at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:271)
       at sun.reflect.GeneratedMethodAccessor29.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
       at java.lang.reflect.Method.invoke(Unknown Source)
       at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:102)
       at $Proxy1.read(Unknown Source)
       at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:370)
       at org.teiid.jdbc.StatementImpl.executeSql(StatementImpl.java:525)
       at org.teiid.jdbc.StatementImpl.executeSql(StatementImpl.java:393)
       at org.teiid.jdbc.StatementImpl.executeQuery(StatementImpl.java:327)
       at com.lgc.dsl.client.ppdmdefect.jdbc.ReadTeiidWithJDBCDriverWorker.readEntitiesFromPPDM(ReadTeiidWithJDBCDriverWorker.java:79)
       at com.lgc.dsl.client.ppdmdefect.jdbc.ReadTeiidWithJDBCDriverWorker.run(ReadTeiidWithJDBCDriverWorker.java:31)
       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
       at java.lang.Thread.run(Unknown Source)
Caused by: org.teiid.core.TeiidException: Batch not found in storage 4537
       at org.teiid.client.ResultsMessage.setException(ResultsMessage.java:202)
       at org.teiid.dqp.internal.process.RequestWorkItem.sendError(RequestWorkItem.java:957)
       at org.teiid.dqp.internal.process.RequestWorkItem.close(RequestWorkItem.java:543)
       at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:346)
       at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:51)
       at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:248)
       at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:269)
       at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
       at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:214)
       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
       at java.lang.Thread.run(Thread.java:662)
Caused by: java.lang.AssertionError: Batch not found in storage 4537
       at org.teiid.common.buffer.impl.BufferManagerImpl$BatchManagerImpl.getBatch(BufferManagerImpl.java:309)
       at org.teiid.common.buffer.TupleBuffer.getBatch(TupleBuffer.java:289)
       at org.teiid.dqp.internal.process.RequestWorkItem.sendResultsIfNeeded(RequestWorkItem.java:803)
       at org.teiid.dqp.internal.process.RequestWorkItem.processMore(RequestWorkItem.java:462)
       at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:320     

Can you please provide us with some pointers as to what can be done to tune the application?

[rareddy]

What are max connections set for for SQL-Server data source connection pool? If all the 40 are concurrent requests, why there are only 2 active sessions and 1 active plan?

Ramesh..

[anilallewar]

The minimum connection set for the SQL server data connection pool are 20 and the max connections set are 50.

The snapshot was taken at the end by when most of the threads had completed so as to give the count at the end; that's why we see only 2 sessions and 1 active plan.

Anil

[van.halbert]

Can you try this for tuning:

Based on the max concurrent queries, start with the following to tune the Teiid engine:

• set maxActivePlans to the max concurrent queries
• set maxThreads = maxActivePlans * 2 (if transactions will be used, then * 3)
• set each datasource max pool size = max conncurrent source queries (minimum would be max conncurrent queries, but if majority of queries are complex in which there are subqueries that cause multiple source queries to be spawned, then max pool size should be increased accordingly),
• after the above adjustments are done and the server has memory room, then consider increasing the processBatchSize and connectorBatchSize (i.e., 512, 1024, respectfully) to increase through-put from the data sourse and thru the engine. If you're out of memory, then increase the JVM size. A machines that has < 6GB memory, stick with 512, larger machines use higher sizes.

[rareddy]

* What kind of query? is query being pushed down as expected? check the command log SQL statements.

* are you using prepared stmts? that may save some planning time.

* How are load testing it? are both being tested with same tool under same scenario, number of machines, concurrent threads and connection  pool etc?

* are you walking the results? what kind of cursor you are using if you are doing it?

* are you counting connection times?

* from command log, you can also figure out what were the source timings, what do they say, still 2 secs?

Teiid does add some overhead especially with quick queries with parsing and planning but not the levels you are seeing, there got to be something else going on.

[anilallewar]

1. The Query is a SELECT some columns from table. It is being pushed down to the source system as expected.

2. Not using prepared statements as no parameters are involved; it's a SELECT columns FROM table.

3. Both are testing from the same machine and going against the same database. However for direct SQL Server connection I am creating one connection per thread whereas for Teiid it would use the source connection from the datasource connection pool. The datasource connection pool has 20 minimum, 50 maximum with pre-fill set to "true".

4. I am just printing the contents of first 1000 rows in the returned resultset.

5. Yes, I am counting the through time for retrieval and that includes the connection time.

6. Please see the table below for the time taken by Teiid to execute the query and bring the resultset into Teiid on the server side. Interestingly the time taken between the START and END source timings varies from 24 sec to 107 secs; I am assuming that rest of the time required on the client would be because of the I/O.

Sr #	Request ID	Start Time	End Time	Elapsed Time For Query
1.	fyAfVZ8xwOdd.0	2014-02-27 13:00:20	2014-02-27 13:00:46	0:26
2.	bXlX1MnxKAY+.0	2014-02-27 13:00:20	2014-02-27 13:01:22	1:02
3.	KDOjnzDDJSKV.0	2014-02-27 13:00:20	2014-02-27 13:01:09	0:49
4.	4fWOXXSjH6ab.0	2014-02-27 13:00:20	2014-02-27 13:00:51	0:31
5.	QdUoWs506ZM7.0	2014-02-27 13:00:20	2014-02-27 13:01:47	1:27
6.	AIwt1aAT7y7k.0	2014-02-27 13:00:20	2014-02-27 13:01:59	1:39
7.	9sonFcG513If.0	2014-02-27 13:00:20	2014-02-27 13:01:11	0:51
8.	jGctIPCW0Io4.0	2014-02-27 13:00:20	2014-02-27 13:01:25	1:05
9.	OYSV9lP6j2ZV.0	2014-02-27 13:00:20	2014-02-27 13:01:39	1:19
10.	n66Z4H5OiUeK.0	2014-02-27 13:00:20	2014-02-27 13:00:52	0:32
11.	oTmkkPUlR4rs.0	2014-02-27 13:00:20	2014-02-27 13:01:39	1:19
12.	sVK2nyayGU9O.0	2014-02-27 13:00:20	2014-02-27 13:01:34	1:14
13.	AtV3XLjjBGme.0	2014-02-27 13:00:20	2014-02-27 13:01:54	1:34
14.	REcgCv5CPDzs.0	2014-02-27 13:00:20	2014-02-27 13:01:46	1:26
15.	neIKD9FSqasr.0	2014-02-27 13:00:20	2014-02-27 13:01:15	0:55
16.	j9PGOzA3aj5V.0	2014-02-27 13:00:20	2014-02-27 13:01:21	1:01
17.	rWK/8JqMDwRf.0	2014-02-27 13:00:20	2014-02-27 13:01:19	0:59
18.	CkNNePtg/d8T.0	2014-02-27 13:00:20	2014-02-27 13:01:41	1:21
19.	hC2EMk6Mkjwi.0	2014-02-27 13:00:20	2014-02-27 13:01:52	1:32
20.	qhOz+aYIRXf3.0	2014-02-27 13:00:20	2014-02-27 13:01:38	1:18
21.	baO4jxsxtp1k.0	2014-02-27 13:00:20	2014-02-27 13:00:44	0:24
22.	PjHG5vNPPhrJ.0	2014-02-27 13:00:44	2014-02-27 13:02:31	1:47
23.	7s1dk/P+a5v8.0	2014-02-27 13:00:46	2014-02-27 13:02:03	1:17
24.	X4J7xL9Go5cC.0	2014-02-27 13:00:51	2014-02-27 13:02:30	1:39
25.	aL6e0kDSif0Z.0	2014-02-27 13:01:09	2014-02-27 13:02:20	1:11
26.	i3Sjk+NtyljY.0	2014-02-27 13:01:11	2014-02-27 13:02:52	1:41
27.	nIAFhYUH6xLO.0	2014-02-27 13:01:15	2014-02-27 13:02:55	1:40
28.	Gqoe27PhGEM1.0	2014-02-27 13:01:21	2014-02-27 13:02:42	1:21
29.	94//wTy7AO9h.0	2014-02-27 13:01:22	2014-02-27 13:03:01	1:39
30.	pSweo7uSHdPX.0	2014-02-27 13:01:25	2014-02-27 13:02:57	1:32
31.	JYPjkKVV9ESi.0	2014-02-27 13:01:34	2014-02-27 13:03:09	1:35
32.	Kdk2TrSgeE67.0	2014-02-27 13:01:38	2014-02-27 13:03:02	1:24
33.	0QyI44Brcf1y.0	2014-02-27 13:01:39	2014-02-27 13:03:07	1:28
34.	D/OrEvdsqeT4.0	2014-02-27 13:01:39	2014-02-27 13:02:46	1:07
35.	QUJqCTgS39k2.0	2014-02-27 13:01:41	2014-02-27 13:03:24	1:43
36.	deCHBuLA0JKS.0	2014-02-27 13:01:46	2014-02-27 13:03:22	1:36
37.	pINHBhAaQYX7.0	2014-02-27 13:01:47	2014-02-27 13:03:29	1:42
38.	GtLT/RZlXI4C.0	2014-02-27 13:00:52	2014-02-27 13:02:34	1:42
39.	sIK4gDn/XwFf.0	2014-02-27 13:01:19	2014-02-27 13:02:42	1:23
40.	Pt7H3mom87YW.0	2014-02-27 13:01:52	2014-02-27 13:03:28	1:36

I will try out the suggested adjustments and post if I see any changes in the behavior.

Anil

[van.halbert]

Since you are making the connection in the app server (or thats what it appears like), is your Teiid connection URL you are using a Teiid Local Connection (no host or port is specified,  ex:  jdbc:teiid:VDBName)?

Also, can you post the sql query you are executing?

Thanks.

Van

[shawkins]

Can you post your test client code?

[anilallewar]

No, I am connecting to Teiid using a socket connection. I am currently just executing the test program to see what is the response if I connected to Teiid from a standalone program; I just run multiple copies of that standalone program in concurrent threads.

Here are the execution details; apparently this took 3 mins to execute the query on Teiid side.

16:48:53,535 DEBUG [org.teiid.COMMAND_LOG] (Worker36_QueryProcessorQueue36)

START DATA SRC COMMAND:

startTime=2014-02-27 16:48:53.535

requestID=cxfwCMusX0J+.0

sourceCommandID=1

executionID=32

txID=TransactionImple < ac, BasicAction: 0:ffff8684ce6c:13638dd6:530fbf48:2d status: ActionStatus.RUNNING >

modelName=DSPMSrc

translatorName=sqlserver

sessionID=cxfwCMusX0J+

principal=user@dsds-security-domain

sql=SELECT g_0.ACTIVE_IND, g_0.ACTIVITY_TYPE, g_0.ALLOWABLE_VOLUME, g_0.ALLOWABLE_VOLUME_OUOM, g_0.CUM_VOLUME, g_0.DATE_FORMAT_DESC, g_0.EFFECTIVE_DATE, g_0.END_DATE, g_0.EXPIRY_DATE, g_0.MMBTU_VOLUME, g_0.PDEN_ID, g_0.PDEN_VOL_SUMMARY_ALLOCATED_ID, g_0.PERIOD_TYPE, g_0.POTENTIAL_VOLUME, g_0.POTENTIAL_VOLUME_OUOM, g_0.PRODUCT_NAME, g_0.PUBLISHED_VERSION, g_0.REMARK, g_0.REPORT_IND, g_0.ROW_CHANGED_BY, g_0.ROW_CHANGED_DATE, g_0.ROW_CREATED_BY, g_0.ROW_CREATED_DATE, g_0.ROW_QUALITY_NAME, g_0.START_DATE, g_0.VOLUME, g_0.VOLUME_DATE, g_0.VOLUME_OUOM, g_0.VOLUME_QUALITY, g_0.VOLUME_QUALITY_OUOM, g_0.VOLUME_UOM, g_0.YTD_VOLUME FROM DSPMSrc.DS_PDEN_VOL_SUMMARY_ALLOCATED_VW AS g_0

16:51:53,943 DEBUG [org.teiid.COMMAND_LOG] (Worker21_QueryProcessorQueue368)

END SRC COMMAND:

endTime=2014-02-27 16:51:53.943

requestID=cxfwCMusX0J+.0

sourceCommandID=1

executionID=32

txID=TransactionImple < ac, BasicAction: 0:ffff8684ce6c:13638dd6:530fbf48:2d status: ActionStatus.RUNNING >

modelName=DSPMSrc

translatorName=sqlserver

sessionID=cxfwCMusX0J+

principal=user@dsds-security-domain

finalRowCount=768075

I tried with the following combination of batch sizes and also by trying to move memory off-heap. No significant changes in the performance.

<async-thread-pool>teiid-async</async-thread-pool>
 <buffer-service processor-batch-size="1024" connector-batch-size="4096" memory-buffer-off-heap="true"/>
 <max-threads>120</max-threads>
 <max-active-plans>40</max-active-plans>
 
<bounded-queue-thread-pool name="teiid-async">
                <queue-length count="1000"/>
                <max-threads count="30"/>
 </bounded-queue-thread-pool>

increased the processor batch size and tried both off an on heap memory; the performance is better by about 20 secs for the last query when the memory is off heap.

<buffer-service processor-batch-size="1024" connector-batch-size="4096" memory-buffer-off-heap="false"/>

Anil

[shawkins]

Anil,

You should revert all of the configuration changes that you have made.  In most situations you should see similar performance characteristics with making a direct call vs. a call through Teiid.  So it would help to start with simple assumptions and fine tune from there.  Note that the teiid-async pool is only for AS administrative tasks, like loading vdbs, and is not used by the runtime engine.

Can you provide your test client code?  And can you run your test client code directly against the database and ideally in an AS container to get baseline comparisons?

We'll circle back to the exception you saw earlier at a later time.

Steve

[anilallewar]

Here is the sample code

Main class

/**
  * @param args
  */
  public static void main(String[] args) {
  ReadLargeDSPMData readData = new ReadLargeDSPMData();
  readData.readDataUsingJDBC();
  }

/**
  * Read data using jdbc.
  */
  private void readDataUsingJDBC() {
  int runCycles = 40;
  ExecutorService readPdmDataThreadExecutor = Executors
  .newFixedThreadPool(runCycles);

  Runnable worker = null;

  // Create separate thread for each cycle
  for (int i = 1; i <= runCycles; i++) {
  worker = new ReadTeiidWithJDBCDriverWorker(i);
  readPdmDataThreadExecutor.execute(worker);
  }

  readPdmDataThreadExecutor.shutdown();
  }

Please see the worker thread class attached.

I would work on simulating the behavior on App server using direct SQL server connection from the data source and post the results.

[van.halbert]

I know you're trying to compare apples to apples (so to speak), but including reading the DatabaseMetadata is normally not part of performance testing when it comes to expected query performance.      And when applications use database metadata, they tend to cache it, because it generally doesn't change during the users session and it improves performance  by not retrieving it each time.

Van

[shawkins]

A couple notes.  Avoid sys out in the test code especially if there is a large data volume as that is effectively a somewhat slow synchronized operation.  Also make sure for a baseline comparison that you are using a transaction in the other test scenarios.  Be aware though In the Teiid case setAutoCommit(false) will go beyond just a local transaction as it must use an XA transaction if possible in the container.  So if there are possible table locking issues, then that is a likely point of contention.

Steve

[shawkins]

Van,

What DatabaseMetadata are you referring to?

[van.halbert]

...

  ResultSetMetaData rsMetadata = resultSet.getMetaData();

  StringBuilder sb = new StringBuilder();

...

Its not the getDatabaseMetadata() call, but is essentially the same.