• Forums
    • Public Forums
      • Community Connect
      • Dynatrace
        • Dynatrace Open Q&A
      • Application Monitoring & UEM
        • AppMon & UEM Open Q&A
      • Network Application Monitoring
        • NAM Open Q&A
  • Home
  • Public Forums
  • Application Monitoring & UEM
  • AppMon & UEM Open Q&A
avatar image
Question by Satish P. · Nov 03, 2012 at 07:02 AM ·

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?

Comment

People who like this

0 Show 0
10 |2000000 characters needed characters left characters exceeded
  • Viewable by all users
  • Viewable by moderators
  • Viewable by moderators and the original poster
  • Advanced visibility
Toggle Comment visibility. Current Visibility: Viewable by all users

Up to 10 attachments (including images) can be used with a maximum of 50.0 MiB each and 250.0 MiB total.

2 Replies

  • Sort: 
  • Most voted
  • Newest
  • Oldest
avatar image

Answer by Rob V. · Nov 03, 2012 at 07:44 AM

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

Comment

People who like this

0 Show 1 · Share
10 |2000000 characters needed characters left characters exceeded
  • Viewable by all users
  • Viewable by moderators
  • Viewable by moderators and the original poster
  • Advanced visibility
Toggle Comment visibility. Current Visibility: Viewable by all users

Up to 10 attachments (including images) can be used with a maximum of 50.0 MiB each and 250.0 MiB total.

avatar image Satish P. · Nov 08, 2012 at 06:16 AM 0
Share

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.

avatar image

Answer by Satish P. · Nov 03, 2012 at 07:06 AM

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.

Comment

People who like this

0 Show 0 · Share
10 |2000000 characters needed characters left characters exceeded
  • Viewable by all users
  • Viewable by moderators
  • Viewable by moderators and the original poster
  • Advanced visibility
Toggle Comment visibility. Current Visibility: Viewable by all users

Up to 10 attachments (including images) can be used with a maximum of 50.0 MiB each and 250.0 MiB total.

How to get started

First steps in the forum
Read Community User Guide
Best practices of using forum

NAM 2019 SP5 is available


Check the RHEL support added in the latest NAM service pack.

Learn more

LIVE WEBINAR

"Performance Clinic - Monitoring as a Self Service with Dynatrace"


JANUARY 15, 3:00 PM GMT / 10:00 AM ET

Register here

Follow this Question

Answers Answers and Comments

2 People are following this question.

avatar image avatar image

Forum Tags

dotnet mobile monitoring load iis 6.5 kubernetes mainframe rest api dashboard framework 7.0 appmon 7 health monitoring adk log monitoring services auto-detection uem webserver test automation license web performance monitoring ios nam probe collector migration mq web services knowledge sharing reports window java hybris javascript appmon sensors good to know extensions search 6.3+ server documentation easytravel web dashboard kibana system profile purelytics docker splunk 6.1 process groups account 7.2 rest dynatrace saas spa guardian appmon administration production user actions postgresql upgrade oneagent measures security Dynatrace Managed transactionflow technologies diagnostics user session monitoring unique users continuous delivery sharing configuration alerting NGINX splitting business transaction client 6.3 installation database scheduler apache mobileapp RUM php dashlet azure purepath agent 7.1 appmonsaas messagebroker nodejs 6.2 android sensor performance warehouse
  • Forums
  • Public Forums
    • Community Connect
    • Dynatrace
      • Dynatrace Open Q&A
    • Application Monitoring & UEM
      • AppMon & UEM Open Q&A
    • Network Application Monitoring
      • NAM Open Q&A