Database "exec avg" time inconsistencies..
As i'm getting such excellent support from this forum, i'd like to discuss / brainstorm another "weird" scenario in my Dynatrace-instrumented app.
I'm using DT to monitor a .Net ETL job. To simply, it does the following:
1) Call a SQL 2012 sproc, that returns 150K rows of data
2) Process above data
3) Write out summarized data to destination.
I'm having difficulty correlating the "database exec avg" value for this sproc in the "Database" dashlet.
I'm using ADO.NET / .Net 4.0.
I'm also using the .Net Enterprise Library for calling the SQL sproc.
So the code kind of looks like:
CallSproc()
{
SET sproc params into DBCommand
public virtual System.Data.DataSet ExecuteDataSet(System.Data.Common.DbCommand command)
Member of Microsoft.Practices.EnterpriseLibrary.Data.Database
CALL public virtual System.Data.DataSet Microsoft.Practices.EnterpriseLibrary.Data.Database.ExecuteDataSet(System.Data.Common.DbCommand command)
ie : [http://msdn.microsoft.com/en-us/library/bb748692(v=pandp.50).aspx|http://msdn.microsoft.com/en-us/library/bb748692(v=pandp.50).aspx]
Source code: http://entlib.codeplex.com/SourceControl/changeset/view/99885#527021
Above method is explicitly instrumented in Dynatrace. The purepath shows the following (partial output):
Level |
Method |
Argument |
Exec Total [ms] |
Class |
4 |
ExecuteDataSet(DbCommand) |
|
14837.2 |
Database |
5 |
LoadDataSet(DbCommand, DataSet, String[]) |
|
14837.2 |
Database |
6 |
DoLoadDataSet(DbCommand, DataSet, String[]) |
|
14837.2 |
Database |
7 |
Fill(DataSet) |
|
14837.2 |
DbDataAdapter |
8 |
Fill(DataSet, int, int, String, IDbCommand, CommandBehavior) |
|
14837.2 |
DbDataAdapter |
9 |
FillInternal(DataSet, DataTable[], int, int, String, IDbCommand, CommandBehavior) |
|
14837.2 |
DbDataAdapter |
10 |
System.Data.IDbCommand.ExecuteReader(CommandBehavior) |
** sproc name** |
472.5734 |
DbCommand |
10 |
Fill(DataSet, String, IDataReader, int, int) |
|
14364.62 |
DataAdapter |
11 |
FillFromReader(DataSet, DataTable, String, DataReaderContainer, int, int, DataColumn, Object) |
|
14364.62 |
DataAdapter |
12 |
FillLoadDataRow(SchemaMapping) |
|
49.70458 |
DataAdapter |
12 |
FillNextResult(DataReaderContainer) |
|
99.40915 |
DataAdapter |
12 |
FillLoadDataRow(SchemaMapping) |
|
14215.51 |
DataAdapter |
So ExecuteDataSet took almost 15 seconds to complete. This is consistent with SQL Server timings, via say SQL Profiler Trace, or manual execution of the sproc from Query Analyzer.
But, the "Database Dashlet" says something else completely! If i drill down to "Database" from the above purepath, i get:
Level |
SQL |
Type |
RT/Trans [ms] |
Acqu Time/Trans [ms] |
Executions/Trans |
Exec Avg [ms] |
Exec Min [ms] |
Exec Max [ms] |
Acqu Avg [ms] |
Acqu Total [ms] |
Exec Total [ms] |
Executions |
Failed % |
Preparations |
Max Pool Usage |
Min Pool Usage |
Acqu Min [ms] |
Acqu Max [ms] |
Last Pool Usage |
Pool Size |
Agent |
Response Time [ms] |
RT/Exec [ms] |
RT/calling Transaction [ms] |
RT Contribution |
Execs/calling Transaction |
% of Transactions Calling |
Platform |
2 |
*sproc name* |
SQL Server |
472.5734 |
- |
1 |
472.5734 |
472.5734 |
472.5734 |
- |
- |
472.5734 |
1 |
0 |
0 |
0.01 |
0.01 |
- |
- |
0.01 |
100 |
<NULL> |
472.5734 |
472.5734 |
472.5734 |
0.031779 |
1 |
1 |
.NET |
400 ms "exec avg" does not match 15 seconds of execution time.
So what exactly is being measured/reported by the "Database" dashlet?
wanted to add.. this feels like a bug.. ie, its not accurate to report the execution time of DBCommand.ExecuteReader as the sproc execution time in "Database" dashlet.. obviously there is more going on with the large result set that is being streamed back to the client via Fill / Load etc.
Hi Satish,
I see both points of view. From the standpoint of a person opening ISQL and running a query, it took 15 seconds for that to finish (executing the query and returning the data, all as an atomic operation). But under the covers it's multiple steps. The execution of the sproc took 472.5734 ms, at which point the data was ready to be processed or discarded or whatever. Then came the streaming of the data. So in that sense the DBMS engine took the 472 ms that are being reported.
So perhaps this is an enhancement request to show both things. It's definitely interesting to see how the DBMS engine is performing to get to the "first byte". But it's also reality to be concerned with when the streaming of data is complete. Perhaps the thing to do is have two times, much like the difference between "PurePath Response Time" and "PurePath Duration", where we present the time to exec the sproc (to first byte time) and the time to finish the sproc (process the result set). Both numbers seem interesting to me. Are you interested in doing another enhancement request?
Rob
thanks Rob.. will do.
I think the ado.net sensor needs some tweaking.. ie its probably not equivalent to clump in ExecuteReader in the same bucket as ExecuteNonQuery.. based on the screenshot you shared earlier.. https://apmcommunity.compuware.com/community/download/attachments/94766578/adoDotNetSensors.png
As you commented, they have different performance characteristics / algorithms.
