Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Instrumented code to measure execution time of the various layers #1023

Merged
merged 8 commits into from
Aug 13, 2021

Conversation

bart-degreed
Copy link
Contributor

@bart-degreed bart-degreed commented Jun 28, 2021

This PR instruments the various layers of code in the library and the example project. It enables identification of code paths worth considering for optimization.

Fixes #1032.

Example output:

JsonApiDotNetCoreExample.Startups.Startup: Information: Measurement results for application startup:
Configure other (startup) .........  0:00:00:00.0018732 ...   0.17%
  Configure JSON:API (startup) ....  0:00:00:01.0907241 ...  99.83%
Initialize other (startup) ........  0:00:00:00.5180028 ...  98.60%
  Initialize JSON:API (startup) ...  0:00:00:00.0073801 ...   1.40%

JsonApiDotNetCore.Middleware.JsonApiMiddleware: Information: Measurement results for GET http://localhost:14140/api/v1/todoItems?include=owner,assignee,tags:
JSON:API middleware .................................  0:00:00:00.0000286 ...   1.14%
  Subsequent middleware .............................  0:00:00:00.0002976 ...  11.86%
    Parse query string ..............................  0:00:00:00.0000360 ...   1.43%
    Service - Get resources .........................  0:00:00:00.0001394 ...   5.55%
      Repository - Count resources ..................  0:00:00:00.0000030 ...   0.12%
        Convert QueryLayer to System.Expression .....  0:00:00:00.0001265 ...   5.04%
          Convert System.Expression to IQueryable ...  0:00:00:00.0000009 ...   0.04%
        Execute SQL (count) .........................  0:00:00:00.0122070
      Top-level query composition ...................  0:00:00:00.0000984 ...   3.92%
      Nested query composition ......................  0:00:00:00.0000351 ...   1.40%
      Repository - Get resource(s) ..................  0:00:00:00.0000021 ...   0.08%
        Convert QueryLayer to System.Expression .....  0:00:00:00.0003258 ...  12.98%
          Convert System.Expression to IQueryable ...  0:00:00:00.0000013 ...   0.05%
        Execute SQL (data) ..........................  0:00:00:00.0124639
    Write response body .............................  0:00:00:00.0004246 ...  16.92%
      Serializer.Build (list) .......................  0:00:00:00.0007376 ...  29.39%
      Newtonsoft.Serialize ..........................  0:00:00:00.0002527 ...  10.07%

Note that the percentages in non-leaves indicate the relative time spent in that call, they are not cumulative. For example, in the request above, the relative time spent in "Write response body" is 16.92% (self) + 29.39% + 10.07% (children) = ~55%.

@bart-degreed bart-degreed force-pushed the instrumentation branch 4 times, most recently from 0724ba2 to 1decbd5 Compare June 30, 2021 13:19
@codecov
Copy link

codecov bot commented Jun 30, 2021

Codecov Report

Merging #1023 (aac3085) into master (d555bb5) will decrease coverage by 1.76%.
The diff coverage is 54.25%.

❗ Current head aac3085 differs from pull request most recent head 3904223. Consider uploading reports for the commit 3904223 to get more accurate results
Impacted file tree graph

@@            Coverage Diff             @@
##           master    #1023      +/-   ##
==========================================
- Coverage   91.63%   89.86%   -1.77%     
==========================================
  Files         252      258       +6     
  Lines        6777     7027     +250     
==========================================
+ Hits         6210     6315     +105     
- Misses        567      712     +145     
Impacted Files Coverage Δ
.../JsonApiDotNetCoreExample/Startups/EmptyStartup.cs 0.00% <ø> (ø)
...sonApiDotNetCore/Diagnostics/CascadingCodeTimer.cs 10.18% <10.18%> (ø)
...piDotNetCore/Diagnostics/AspNetCodeTimerSession.cs 15.38% <15.38%> (ø)
...DotNetCore/Diagnostics/CodeTimingSessionManager.cs 41.66% <41.66%> (ø)
...iDotNetCore/Diagnostics/DefaultCodeTimerSession.cs 60.00% <60.00%> (ø)
...JsonApiDotNetCore/Diagnostics/DisabledCodeTimer.cs 83.33% <83.33%> (ø)
.../JsonApiDotNetCore/Middleware/JsonApiMiddleware.cs 97.72% <89.65%> (-2.28%) ⬇️
...mples/JsonApiDotNetCoreExample/Startups/Startup.cs 95.83% <94.73%> (-4.17%) ⬇️
...onApiDotNetCore/Diagnostics/MeasurementSettings.cs 100.00% <100.00%> (ø)
...iDotNetCore/Queries/Internal/QueryLayerComposer.cs 100.00% <100.00%> (ø)
... and 17 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update d555bb5...3904223. Read the comment docs.

@bart-degreed bart-degreed force-pushed the instrumentation branch 5 times, most recently from b6087e7 to 23e5639 Compare August 5, 2021 12:13
@bart-degreed bart-degreed marked this pull request as ready for review August 5, 2021 12:28
@bart-degreed bart-degreed force-pushed the instrumentation branch 8 times, most recently from e468af4 to 5b637d2 Compare August 10, 2021 08:38
@bart-degreed
Copy link
Contributor Author

Reverted Resharper/Rider update due to hanging cibuild. Tracked at https://youtrack.jetbrains.com/issue/RSRP-481371#focus=Comments-27-5106579.0-0.

Copy link
Member

@maurei maurei left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added two comments earlier

@bart-degreed bart-degreed merged commit 2f157a5 into master Aug 13, 2021
@bart-degreed bart-degreed deleted the instrumentation branch August 13, 2021 12:25
@bart-degreed bart-degreed mentioned this pull request Sep 14, 2021
5 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

Add an easy way to measure time spent in layers
2 participants