1 2 Previous Next 27 Replies Latest reply on Feb 28, 2013 7:11 PM by shawkins

    performance statistics for teiid query

    yjma2001

      Hi:

       

      When teiid does a query, there are two part of processing, one part is depending on the data source, another part is teiid itself processing. for some time-consuming queries, in order to determine the bottleneck of query, we want to know how much time spends on the query from the  data source, and how much time spends on the teiid processing itself, etc.

       

      Is teiid currently providing such performance statistics in any way?

       

      Thanks

      Jack

        • 1. Re: performance statistics for teiid query
          markaddleman

          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

            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

              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

                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

                  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

                    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

                      requestID should be unique for different nodes

                      • 8. Re: performance statistics for teiid query
                        yjma2001

                        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

                          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

                            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

                              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

                                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

                                  An enhancement issue https://issues.jboss.org/browse/TEIID-2409 has been opened.

                                  1 of 1 people found this helpful
                                  • 14. Re: performance statistics for teiid query
                                    yjma2001

                                    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

                                    1 2 Previous Next