What does MiniProfiler information mean?

1

I’m trying to profile a web application we’re using but I’m struggling to understand the meaning of everything that’s displayed in MiniProfiler output. Here’s what I have:

duration (ms)	from start (ms)	query time (ms)
https://1df	 3118.7	+0.0	 ! 6 sql	 1577.0
  	                                  50.6 % in sql
client event	         duration (ms)	from start (ms)
Response	                 177.0	        +3861.0
Unload Event	             6.0	        +3862.0
Dom Content Loaded Event	 217.0	        +5443.0
Load Event	                 7.0	        +6434.0
Dom Complete		                        +6434.0
share show trivial

Which I interpret as the “server” time for the request is taking 3118 ms, of which roughly 50% is due to DB queries and the rest is due to application logic. If I want to further refine that I understand I just have to add steps to the appropiate page logic to determine the bottlenecks.

However, the actual page takes almost 6 and a half seconds from the moment, that is almost 3 seconds from the moment the response is received til is finally displayed to the user.

What is that times spend into? Is there anyway with Miniprofiler to see what’s going on under the hood and determine where time is being spend (this is a “fast” example, sometimes the server time is 300 ms but the other part accounts for 10 seconds, which is simply not acceptable)

Note: configuration debug is set to false in this particular example.

2
  • The request spent 3118.7ms on the server (51.7% of that was in sql)
  • Response received on the client at 3861ms (so 742.2ms of transit time)
  • The rest of the time between 3861ms and 6434ms is page content and javascript loading and rendering time, all in the browser
3

Hi All

I love Miniprofiler. It has helped me tremendously especially for finding things like n+1 queries. However, as the low hanging fruit becomes harder to find the miniprofiler output becomes harder to understand.

Unfortunately, I can’t upload a screen shot so I’ll just past the output text here. If I try to follow the data using the timestamps as a guide I’m lost immediately because sometimes the output is sometimes adds more confusion rather than illuminate the problem.

I’ve reproduced a sample of the mini profiler output from my production rails app. How do I investigate this gap 3667.80ms? It’s not clear what the source is since it looks like the step before only took 123ms in total.

Thanks

Gap: 29.90 ms

Executing action: create — 29.90 ms
Executing action: create
T+122.9 ms
Reader
0.1 ms
[STACKTRACE 1]
[SQL SELECT STATEMENT ]

GAP 3667.80 ms – Executing action: create — 2931.42 ms

Executing action: create
T+3790.8 ms
Reader
1.2 ms

[STACKTRACE2]
BEGIN

Gap 29.90 ms – Executing action: create — 29.90 ms

Executing action: create
T+3821.9 ms
Reader
0.1 ms

[STACKTRACE 3]

[SQL INSERT STATEMENT]

GAP: 738.00 ms Net::HTTP PUT /tiles/7697/8227850cd103ca78200fb21415e6f4a8f0636f4e__screen_shot_2015-07-15_at_2-09-11_pm.png — 596.70 ms

Executing action: create
T+4560.0 ms
Reader
5.0 ms
[STACKTRACE 3]
COMMIT