SQL Query execution time

[madhancog]

Hi gurus,
  Let me know how to find the SQL Query execution time in cognos8.
  example
     when we run the report it will takes 2 mins,now can i know where can i find the time taken to execute the SQL query and time taken to create the report.

KRs
K.M

[NaviGator]

I don't think that you can find this.

You will only be able to know the Start time and End Time for the Report execution. Even this will be available only for the scheduled report or saved report.

[geoff1984]

We looked for this too.  I think NaviGator is right.

The only thing I can think of would be to monitor the database while running a single, isolated report and attempt to see which database queries are generated by Cognos and how long they take.

If you come up with some other answer I would love to hear it.

[NaviGator]

We looked for this too.  I think NaviGator is right.

The only thing I can think of would be to monitor the database while running a single, isolated report and attempt to see which database queries are generated by Cognos and how long they take.

If you come up with some other answer I would love to hear it.

Or, you can take the query from the report and run it on Toad or any other tool. You can then get the exact execution time for the query.

[smiley]

Or run it in a stripped down copied report in Cognos, with just the sql in it, making sure you have 0 local processing, and write the results to audit database.
Subtract a 3 scond variable for a theoretical start of a fresh bibus, and your data should be pretty accurate.
Easy to report on also. Just compare the real deal with your stripped down one in runtime via the audit db.

[AussiePete2011]

Hi there

I'd suggest if you want to find out more about a specific performance issue with a report that you look at turning on the QFS logging which you will find in the ipfPERFclientconfig.xml.sample file under the ../<c8install>/configuration folder.

<!--category name="Perf.QFS" class="com.cognos.indications.LogTypedLogger">
      <level value="info"/>
</category-->

Basically you need to do the following
1.   Make a copy of the ipfPERFclientconfig.xml.sample file
2.   Rename the copy to ipfclientconfig.xml
3.   Open the file in a text editor and uncomment the line above to enable logging.
4.   Wait approximately 1 minute or so
5.   Logon to Cognos Connection
6.   Run the report you wish to work out the SQL execution times
7.   Look under the logs folder for a file called c8_performance.log

I'd do this test for a report in a low load period in isolation of the current users base so that you capture this particular report.

The output should show you all aspects of the report run broken down into timed segments.  This is a deep trace of a report and can show you exactly where the bottle necks are.

Other suggests provided thus far will give you the SQL execution time which will help you tune either your model or your report but will not provide you the information of how the SQL gets manipulated from within Cognos itself.  The above information will provide this which will, in combination with the Native SQL execution times provide you a complete overview of how your report is actually running.

Be aware though that the connection to the database, the database tuning, the network and BI 8 Server configuration all have an affect on your overall reporting.

Cheers
Peter B

[NaviGator]

Peter,

Thanks a lot for your comment.

I have followed your steps and now I have the "c8_performance.log" in my logs folder. It would be great if you can give me some hints on how to read this log file and get the required info ..

[AussiePete2011]

Hi there

Ok so first question to ask is
1.  Is the source relational or OLAP?
In the case of relational then we look at the report itself and ask
2.  How many queries are in use in the report?

Once we have this basic information we can then look at the log

What you are looking at is the "et" tag which is in milliseconds.  The best way to read the log is in an XML form so that you can see the tags correctly.  IE will work however if you download a free XML reader you'll get the benefit of capturing information as text.

The log is generated in sections showing total time (et) in millisecnds (ms) of a process involved in the execution of a report.  You can work out from this log where the most time is spent processing the report.

In the log you will hopefully see RQ tags
<RP n="Report Name" rN="0" st="Start Timestamp" et="Runtime Timestamp" status="SUCCESS" >
      <RC><![CDATA[;/content/package[@name='PATH and package name'];asynchRun_Request;]]></RC>
      <RS et="11111111" > (Total runtime)
         <C n="MDOperationProvider" et="111111" > (of Multidimensional query)
            <CF n="QFSQuery::Prepare" et="11111" nc="1" /> (runtime of query execution)
         </C>
         <C n="RelationalQueryProvider" et="1111111" > ( Total runtime of preparation for Relational query processing)


<RQ n="Query1" et="1111111" > (One of the queries used in the report)
         <C n="MDOperationProvider" et="1111111" >  (Performs decomposition of a query that results in a dynamic cube being constructed)
            <CF n="QFSQuery::Prepare" et="111111" nc="1" />
         </C>
         <C n="RelationalQueryProvider" et="111111" >

This discussion is quite complex but at a glance you will be able to determine where the most time is spent in the report and on what process.  Let me know if the above makes sense as it is something that takes a bit of time to get used to but is quite powerful for tuning your reports.

Cheers
Peter B

[PRIT AMRIT]

it is something that takes a bit of time to get used to but is quite powerful for tuning your reports

Peter, I never knew about this technique for tuning the report. Seems very interesting. Have you prepared any sort of documentation for this, which you could share with us?

Really appreciate your valuable inputs, always!!

Thanks
Prit

[AussiePete2011]

Hi Prit,

Unfortunately I had to leave all the documentation with IBM when I left so this is purely off the top of my head.  Sorry about that, but I can certainly attempt to answer questions on this and the generated log file

Cheers and thanks
Peter B

[madhancog]

Hi Gurus,
   I have opened the file in notepad, and i am not able to understand so i tried to open with XMl viewer
i am not able to open the file can you please help me in this issue.

Thanks & Regards,
K.M

[AussiePete2011]

Hi there

Sorry for the long absence been pretty busy of late.
If you have a valid XML then it should open in IE (Internet Explorer) if it doesn;t then its likely the file was not completely written.
Each performance xml file will be created per session for that report.

If you're still interested. what part of the tuning are you looking at?

Cheers
Peter

[madhancog]

Thanks for your kind reply...
I am looking for bottlenecks in the reports
I need to identify what is the exact problem in the report and fix it.
let me know how can i proceed on that.

Thanks in advance
K.M

[AussiePete2011]

Hi there

Ok do you have a copy of the performance trace handy.  If you can look through the log at the various et results, find the highest value you can find and possible the second highest value and add it to the thread.
Also I'd need to know how many queries, whether they are unioned, how many charts, crosstabs and calculations.
Also what database feeds the report and what you have used to connect to the database in the data source connection in Cognos.

Once I have these details we can start sorting out if its a report issue or a connection issue.

Cheers
Peter

[cognos.cognosbi@gmail.com]

Grete Peter...

[Cognos8]

Pete ,

It was awesome information, Is there any IBM link which explains about each IPF trace?

[AussiePete2011]

Hi there,

No, basically, the information is internal to IBM who wont provide it unless you have a PMR with them.  I can explain parts of it but in general terms only.

Actually I have a PMR open with IBM right now asking about information on the  RelationalQueryProvider and under this there are two components that take 90% of the time spent in this component
AQE_QSConnection - ProcessRequest converts the V5 XML request to an internal representation of the V5 request, while AQP_LogicalQuery::Refine is where most of query planning occurs.

In this scenario the SQL runs in 30 seconds however, overall the report takes 12 minutes.  Of the 12 minutes, 90% of that time is in the AQE_QSConnection component.

I used the performance trace to detail the area of the delay so that I could determine if there was anything I could do to increase the performance.  The trace allowed me to cross off the SQL being generated and any connectivity issues.

At this stage, I'm pretty sure its a re-write of the report!
I'm happy to help but there are aspects that need to be addressed when a question is asked regarding performance.

1.  What is the database being used as a source.  Vendor, version and build 
2.  What type of connection in Cognos is used for the data source.
3.  How complex the report is.  E.g charts, crosstabs, unions etc

Depending on the type of model
4.  How the Model or cube was created.  This can be one area that will take time to determine and may be the root cause in 70% of cases.

The above information is very high level and you will need to use tracing, as well as use knowledge of modelling and database design to resolve these issues of performance.

Cheers
Peter

[madhancog]

Hi Peter,
   My report is relational reports.I am doing as a POC to find the bootlenecks in the reports.
I have followed the steps what you said,i got the c8_performance log file.Now i opened the Performance_20110830103112396 xml file.
I am able to see lot many tags,can you just guide me what exactly i need to consider for tuning.
I am attaching the xml along with this.

Thanks
K.M

[AussiePete2011]

Hi there

Sorry about the late reply... Its been really hard to get back here what with the planned upgrades to C10.

I've had a look at the performance log and it seems to be a bit of a delay in the sqlAOpen which would be the attempt to make a connection to the database..  What type of driver is being used and is it at the same version as the database?  Is it NAtive or ODBC?

Have a look at
1.  The database version and build.
2.  Compare this to the Native drivers installed on each Cognos Server and maker sure they are the same version.
3.  If it's ODBC, you can turn on ODBC tracing in the cogdmod.ini file found under the bin folder to compare the performance output with the ODBC trace

[trace]
Output=d:\c8odbc_Cognos.txt
Flags=1111111111
timer=yes

What you should be looking for is the time it takes the SQL to actually hit the database.  The SQL Statement may actually be fine, its the time taken for the SQL to get to the database to be processed.

We did timings here by opening a database client window showing the sessions hitting the database.
We then ran the report and timed the report to see how long it took for the SQL to hit the database and then how long the report took to respond and render in the browser.

For us the issue is the transformation of the report to xml and so leads us to the conclusion that the report needs to be re-written. Yik but there it is.

Cheers
Peter B