-
1. Re: performance statistics for teiid query
markaddleman Feb 22, 2013 11:59 AM (in response to yjma2001)I'm not aware of any built-in Teiid facilities for this. We have written a delegating translator that produces these statistics for all of our data sources and then use the request id to correlate that information with the request from the client. Unfortunately, that code is bound up with some of our proprietary code so I can't immediately post it here.
As an aside, I think it would be cool if Teiid generated stats like this itself and made them available through a system table.
-
2. Re: performance statistics for teiid query
yjma2001 Feb 22, 2013 12:09 PM (in response to markaddleman)Mark, Thanks for the information.
Steve/Ramesh:
Do we have any plan at teiid to implement this feature?
Thanks
Jack
-
3. Re: performance statistics for teiid query
rareddy Feb 22, 2013 12:25 PM (in response to yjma2001)you can capture the command_log which tells you what a user and as well as data query start and end. Using that you can derive such info.
Usually this information only useful if Teiid reported per session/query/datasource. so general statistic saying average query time for all queries in Teiid is 'X' is not meaningful IMO. As a user you are looking for overhead that Teiid is adding. So, I say COMMAND_LOG is best option right now.
In the past we have done, query times from client (which also includes your network latency) to Teiid, then also source query directly to source to calculate the overhead. The COMMAND_LOG, user query times includes time taken to read the all the batches by the client, so if a slow client can skew data.
Any suggestions welcome.
Ramesh..
-
4. Re: performance statistics for teiid query
yjma2001 Feb 22, 2013 2:45 PM (in response to rareddy)Hi Ramesh:
Thanks a lot for the response. They are very useful for us.
Could you please help me fully understand those timestemps?
[org.teiid.COMMAND_LOG] (New I/O server worker #2-1) START USER COMMAND: startTime=2013-02-22 10:28:08.418 requestID=Vm9nu0uqa05h.0
Is this the timestamp when user query starts? Does it Include the waiting time in the waiting queue?
[org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue0) PLAN USER COMMAND: endTime=2013-02-22 10:28:08.605 requestID=Vm9nu0uqa05h.0
Is this the timestamp when teiid finishes the quey planing?
[org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue1) START DATA SRC COMMAND: startTime=2013-02-22 10:28:08.836 requestID=Vm9nu0uqa05h.0
Is this the timestamp when a query is sent to data source?
[org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue13) END SRC COMMAND: endTime=2013-02-22 10:28:09.002 requestID=Vm9nu0uqa05h.0
Is this the timestamp when a query finishes at data source?
[org.teiid.COMMAND_LOG] (Worker9_QueryProcessorQueue7984) END USER COMMAND: endTime=2013-02-22 10:28:28.86 requestID=Vm9nu0uqa05h.0
Is this the timestamp when the user query done?
Thanks
Jack
-
5. Re: performance statistics for teiid query
rareddy Feb 22, 2013 3:46 PM (in response to yjma2001)USER COMMAND = The command supplied by the user. There is only one pair of these for every user query
SRC COMMAND = one pair for each data source query that has been executed by Teiid. There can be number of pairs depending upon your query.
[org.teiid.COMMAND_LOG] (New I/O server worker #2-1) START USER COMMAND: startTime=2013-02-22 10:28:08.418 requestID=Vm9nu0uqa05h.0
Is this the timestamp when user query starts? Does it Include the waiting time in the waiting queue?
Yes, no waiting time is included. Time starts when Teiid starts working on the query for the first time.
[org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue0) PLAN USER COMMAND: endTime=2013-02-22 10:28:08.605 requestID=Vm9nu0uqa05h.0
Is this the timestamp when teiid finishes the quey planing?
Yes
[org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue1) START DATA SRC COMMAND: startTime=2013-02-22 10:28:08.836 requestID=Vm9nu0uqa05h.0
Is this the timestamp when a query is sent to data source?
Yes
[org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue13) END SRC COMMAND: endTime=2013-02-22 10:28:09.002 requestID=Vm9nu0uqa05h.0
Is this the timestamp when a query finishes at data source?
Yes, when execution is closed. i.e all the rows has been read
[org.teiid.COMMAND_LOG] (Worker9_QueryProcessorQueue7984) END USER COMMAND: endTime=2013-02-22 10:28:28.86 requestID=Vm9nu0uqa05h.0
Is this the timestamp when the user query done?
yes, when request is complete. i.e. when statement is closed or all the batches are retrieved.
-
6. Re: performance statistics for teiid query
yjma2001 Feb 22, 2013 4:11 PM (in response to rareddy)Ramesh, Thanks.
For the SRC COMMAND, we saw couple pairsin our test result, but we could not match some of those pairs, since from the endTIme of SRC COMMAND log, there is no way to match back with the START DATA SRC COMMAND. Please see last two END DATA SRC COMMAND, the requestId, sourceCommandId, SesssionId all are same. And the thread id does not help neither.
10:28:09,591 DEBUG [org.teiid.COMMAND_LOG] (Worker2_QueryProcessorQueue75) START DATA SRC COMMAND: startTime=2013-02-22 10:28:09.591 requestID=hRGI2ur5vVaT.0 sourceCommandID=3 txID=null modelName=UsersDB translatorName=sqlserver sessionID=hRGI2ur5vVaT principal=xxx sql=SELECT g_0.UserId AS c_0, g_1.DeptName AS c_1, g_0.Name AS c_2 FROM UsersDB.DB1.dbo.Person AS g_0, UsersDB.DB1.dbo.Department AS g_1 WHERE (g_1.DeptId = g_0.DeptId) AND (g_1.DeptName IN ('Department-7', 'Department-8', 'Department-6')) ORDER BY c_0
10:28:09,636 DEBUG [org.teiid.COMMAND_LOG] (Worker5_QueryProcessorQueue97) END SRC COMMAND: endTime=2013-02-22 10:28:09.636 requestID=hRGI2ur5vVaT.0 sourceCommandID=3 txID=null modelName=UsersDB translatorName=sqlserver sessionID=hRGI2ur5vVaT principal=xxx finalRowCount=3000
10:28:09,752 DEBUG [org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue117) START DATA SRC COMMAND: startTime=2013-02-22 10:28:09.752 requestID=hRGI2ur5vVaT.0 sourceCommandID=4 txID=null modelName=TicketsDB translatorName=sqlserver-override sessionID=hRGI2ur5vVaT principal=catalyst=xxx sql=SELECT g_0.UserId AS c_0, g_0.TicketId AS c_1, g_0.TicketDescription AS c_2, g_0.TicketType AS c_3 FROM TicketsDB.DB2.dbo.Ticket AS g_0 WHERE g_0.UserId IN (...)
10:28:09,754 DEBUG [org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue109) START DATA SRC COMMAND: startTime=2013-02-22 10:28:09.754 requestID=hRGI2ur5vVaT.0 sourceCommandID=4 txID=null modelName=TicketsDB translatorName=sqlserver-override sessionID=hRGI2ur5vVaT principal=xxx sql=SELECT g_0.UserId AS c_0, g_0.TicketId AS c_1, g_0.TicketDescription AS c_2, g_0.TicketType AS c_3 FROM TicketsDB.DB2.dbo.Ticket AS g_0 WHERE (g_0.UserId IN (...))
10:28:11,722 DEBUG [org.teiid.COMMAND_LOG] (Worker9_QueryProcessorQueue2178) END SRC COMMAND: endTime=2013-02-22 10:28:11.722 requestID=hRGI2ur5vVaT.0 sourceCommandID=4 txID=null modelName=TicketsDB translatorName=sqlserver-override sessionID=hRGI2ur5vVaT principal=xxx finalRowCount=200000
10:28:12,625 DEBUG [org.teiid.COMMAND_LOG] (Worker8_QueryProcessorQueue3464) END SRC COMMAND: endTime=2013-02-22 10:28:12.625 requestID=hRGI2ur5vVaT.0 sourceCommandID=4 txID=null modelName=TicketsDB translatorName=sqlserver-override sessionID=hRGI2ur5vVaT principal=xxx finalRowCount=400000
Thanks
Jack
-
7. Re: performance statistics for teiid query
rareddy Feb 22, 2013 4:54 PM (in response to yjma2001)requestID should be unique for different nodes
-
8. Re: performance statistics for teiid query
yjma2001 Feb 22, 2013 7:01 PM (in response to rareddy)RequestId is same for all those SRC COMMANDs. In my sample results, there are three SRC commands in one single user query, they are having same request id. But it is no way to pair last two SRC commands.
-
9. Re: performance statistics for teiid query
rareddy Feb 22, 2013 7:15 PM (in response to yjma2001)Sorry I thought the requestId and sourceCommndID were appended (one time they did), so a combination of the requestID and sourceCommandID would give you the key.
-
10. Re: performance statistics for teiid query
yjma2001 Feb 22, 2013 7:38 PM (in response to rareddy)No, in our test result, the combination of requesId and sourceCommandId is still not unique. Like the example I gave you above, the two SRC commands have same requestId (hRGI2ur5vVaT.0) and sourceCommandID(4).
-
11. Re: performance statistics for teiid query
rareddy Feb 24, 2013 1:15 PM (in response to yjma2001)May be there are multiple calls to same source in a single user query, happens when you can not push some capability down. In the system, there is something called "execution-id" which denotes this distinction between multiple call, however looks like the COMMAND_LOG does not expose it.
In your case, you would want some way to collapse these into one single call, may be first start call, and last end call. Otherwise, you could log enhancement, to provide this info in the COMMAND_LOG
Ramesh..
-
12. Re: performance statistics for teiid query
yjma2001 Feb 24, 2013 4:42 PM (in response to rareddy)Hi Ramesh:
Yes, teiid sends two queries to the data source in this single query. I think it is good idea to add execution id into data src command_log to make the combination key (request id + source command id + execution id) unique. I will open a enhancement issue on it.
Thanks
Jack
-
13. Re: performance statistics for teiid query
yjma2001 Feb 24, 2013 4:57 PM (in response to yjma2001)1 of 1 people found this helpfulAn enhancement issue https://issues.jboss.org/browse/TEIID-2409 has been opened.
-
14. Re: performance statistics for teiid query
yjma2001 Feb 25, 2013 3:05 PM (in response to rareddy)Ramesh Reddy wrote:
USER COMMAND = The command supplied by the user. There is only one pair of these for every user query
SRC COMMAND = one pair for each data source query that has been executed by Teiid. There can be number of pairs depending upon your query.
[org.teiid.COMMAND_LOG] (New I/O server worker #2-1) START USER COMMAND: startTime=2013-02-22 10:28:08.418 requestID=Vm9nu0uqa05h.0
Is this the timestamp when user query starts? Does it Include the waiting time in the waiting queue?
Yes, no waiting time is included. Time starts when Teiid starts working on the query for the first time.
Hi Ramesh:
Looking the teiid code, it looks like that START USER COMMAND is logged before determining if it has to be added into waiting queue. So if we calculate the processing time based on START USER COMMAND and END USER COMMAND, then the processing time will include the waiting time in the waiting queue. I added some comments at issue https://issues.jboss.org/browse/TEIID-2409 to ask to adding more command log, so we could get real teiid processing time.
Thanks
Jack