locked
SQL calls time is calculating not correctly when using DataReader RRS feed

  • Question

  • Hello,

      My project is using NHibernate and MSSQL. NHibernate reads database data row by row, using SQLCommand.ExecuteReader and DataReader.Read functions. Correct SQL call time consists of SQLCommand.ExecuteReader and every DataReader.Read (is called for every selected row) functions call time. AVICode is calculating SQL call time using only ExecuteReader call time.

      Is it possible to configure AVICode to calculate correct SQL calls time when using DataReader.Read function?

    Thanks.


    Thursday, August 4, 2011 7:46 AM

Answers

  • CustomProducer means that it will try to get the custom arguments you will specify above under function tag, so you've created the correct defenition.
    One thing to add - you can also extract separate array members  instead of whole array if you know the required indexes:
    E.g. _items[0] in "0/odbcErrors/System.Data.Odbc.OdbcErrorCollection::_items[0]/System.Data.Odbc.OdbcError::_message".
    But in your case you may need all the parameters, so that's OK.
     
    You can configure AVIcode to show this call as SQL CLient Call - Open PMonitorHandlerV4 and CLRXMonitorHandlerV4 configuration files (under SeViewer installation in Handlers folder) and add aliasing like the next:
     
     <function match="functionName">
      <name>NHibernate.Loader.Loader.DoQuery()</name>
      <aliases>
       <aliasGroup>
        <alias>SQL : '{0}''{1}'</alias>
        <param name="parameters/0"</param>
        <param name="parameters/1"</param>
    and etc...
    </aliasGroup>
    </aliases>
    </function>
    Maybe you can join several parameters - not sure - please check for the sample in those confiugration files.
     
    Also I think you will need to increase detail level limit in the PMonitor.default config for argument to see more lines of the query string:
    <ss:argument name="0/IBM.Data.DB2.iSeries.iDB2Command::Parameters/IBM.Data.DB2.iSeries.iDB2ParameterCollection" detaillevel="3/10" alias="parameters"/> - you can do it on the argument level and on the function level as well - you are interested in increasing the second parameter (the one after the slash).
     

    Dmitry Matveev
    Friday, August 5, 2011 8:20 PM

All replies

  • Hello Fedor,

     

    It's possible but it depends on what you want to find in the event:

    1) To see DataReader.Read calls in the events as Resource Calls:

    - Open your application Settingsd in Intercept Management Console;

    - Add Resource function for your application: DataReader.Read (please, enter the full name with Namespaces and Classes like Microsoft.VisualStudio.Data.DataReader.Read if you use this one);

    - Check the information you want about this resource and threshold for this resource;

    - Recycle AppPool if prompted;

    - Next event will be reported with the calculated time for these calls as well - the stack will contain the sequence of SQl-DataReader calls;

     

    2) To see these calls in the same resource group as SQL calls or in the separate named resource group if you are using "Resource Group" view:

    - Additionally you will need to edit PMonitor2_0.default.config;

    - Open and navigate to <ss:functions> section;

    - Add something similar to the next line but with the required name of the callGroup/function/dll (input "SQL Client Calls" group to make them appear in the same group as MSSQL):

    <ss:function name="Microsoft.VisualStudio.Data.DataReader.Read" module="Microsoft.VisualStudio.Data.dll" callGroup="SQL Data Read calls"/>

    - Save file;

    - If new settings will not be loaded automatically - restart application pool;

     

    Make sure you are experimenting on the Staging/DEV/QA environment - I didn't perform any checks for these instructions myself - just posted them from top of my head.


    Dmitry Matveev
    Thursday, August 4, 2011 10:34 PM
  • Dmitry,

      It is one problem with your solution. Separate DataReader.Read calls are to short to exceed threshold. Actually I want to see ExecuteReader and Read calls as one function call, with one call time.

    Thanks.

    Friday, August 5, 2011 6:42 AM
  • Fedor,

     

    There is no direct solution to join two calls but I see two options here:

    - Configure 0-5 ms threshold for DataReader.Read explicitly - it's allowed because you can configure separate threshold for a resource;

    - Wrap SQl Call together with DataReader.Read call in one function, e.g. ReadSQLForMe() and set up this one as a Resource.

     

    Will it work for you?

     


    Dmitry Matveev

    Friday, August 5, 2011 6:49 AM
  • Dmitry,

      1) With 5ms threshold every Read call will be captured in profiler. But I want to see only slow SQL calls.

      2) I don't want to edit NHibernate source code.

    Fedor.

     

    Friday, August 5, 2011 7:17 AM
  • Fedor,

    Do you know what's the call hierarchy in NHibernate to check if you can setup another function for monitoring that joins these calls?

    I assume that we've disabled NHibernate namespace from timeonly monitoring (from Namespaces section in the Console) in 5.6 or 5.7 by default, so I can't advise you to enable all namespaces and NHiberanate back to track all custom stack points execution times here and find the one you may be interested in.

    You can try to find out such method if you have access to NH source code or assemblies (with Reflector).


    Dmitry Matveev
    Friday, August 5, 2011 7:42 AM
  •  

      I have found NHibernate.Loader.Loader.DoQuery function, wich calls ExecuteReader and Read fucntions.

      I added function to PMonitor2_0.default.config to see SQL expression, wich is stored in array "sqlParts":

     

    			<ss:function name="NHibernate.Loader.Loader.DoQuery" module="NHibernate.dll" methodInfo="ISessionImplementor session, QueryParameters queryParameters, bool returnProxies" paramCount="4">
    				<ss:argument name="0/NHibernate.Loader.Collection.BasicCollectionLoader::SqlString/NHibernate.SqlCommandSqlString::sqlParts/System.Object[]" alias="SQL"/>
    				<ss:instrumentation name="Agent.Instrumentation.InstrumentationClass.CustomProducer" assembly="Agent.Instrumentation"/>
    			</ss:function>
    
    


      Is this correct? I dont know exactly what Agent.Instrumentation.InstrumentationClass.CustomProducer string means.

      Is it possible to conigure AVICode to show NHIbernate DoLoad function info same way as SQL calls (SQL : SELECT ...)?

      

    Friday, August 5, 2011 8:04 AM
  • CustomProducer means that it will try to get the custom arguments you will specify above under function tag, so you've created the correct defenition.
    One thing to add - you can also extract separate array members  instead of whole array if you know the required indexes:
    E.g. _items[0] in "0/odbcErrors/System.Data.Odbc.OdbcErrorCollection::_items[0]/System.Data.Odbc.OdbcError::_message".
    But in your case you may need all the parameters, so that's OK.
     
    You can configure AVIcode to show this call as SQL CLient Call - Open PMonitorHandlerV4 and CLRXMonitorHandlerV4 configuration files (under SeViewer installation in Handlers folder) and add aliasing like the next:
     
     <function match="functionName">
      <name>NHibernate.Loader.Loader.DoQuery()</name>
      <aliases>
       <aliasGroup>
        <alias>SQL : '{0}''{1}'</alias>
        <param name="parameters/0"</param>
        <param name="parameters/1"</param>
    and etc...
    </aliasGroup>
    </aliases>
    </function>
    Maybe you can join several parameters - not sure - please check for the sample in those confiugration files.
     
    Also I think you will need to increase detail level limit in the PMonitor.default config for argument to see more lines of the query string:
    <ss:argument name="0/IBM.Data.DB2.iSeries.iDB2Command::Parameters/IBM.Data.DB2.iSeries.iDB2ParameterCollection" detaillevel="3/10" alias="parameters"/> - you can do it on the argument level and on the function level as well - you are interested in increasing the second parameter (the one after the slash).
     

    Dmitry Matveev
    Friday, August 5, 2011 8:20 PM
  • Hi, As this thread has been quiet for a while, we assume that the issue has been resolved. At this time, we will mark it as "Answered". Either the previous steps should be helpful for many similar scenarios and will be marked as answer, or this post will be marked as answer in order to close the thread. Feel free to re-open the thread if you have additional information about this specific case or to open a new thread for a new case. In addition, we’d love to hear your feedback about the solution. By sharing your experience you can help other community members facing similar problems. Thanks,


    Bob Cornelissen - BICTT (My Blog about SCOM) - MVP 2012 + 2013 and Microsoft Community Contributor 2011 + 2012 Recipient

    Tuesday, March 19, 2013 3:57 PM
    Moderator