MySQL Bugs: #44601: Query Analyzer popup takes 28 seconds to load

Bug #44601	Query Analyzer popup takes 28 seconds to load
Submitted:	1 May 2009 12:00	Modified:	28 Jul 2009 13:02
Reporter:	Diego Medina	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Enterprise Monitor: Server	Severity:	S2 (Serious)
Version:	2.1.0.1032	OS:	Any
Assigned to:	Josh Sled	CPU Architecture:	Any

Description:
From the time I click on a query, to the time I see the pop up, it took 28 seconds to load.

How to repeat:
1- Install and start the servic manager and agent 
2- Have lots of data (9 weeks so far) for 55 servers
3- Click on a query and wait
4- Note the time it takes to load.

Note: Will post the detail timing log

2009-05-01 13:41:51,857 DEBUG [http-18080-5:com.mysql.timing.accessLog.action] /QuerySummaryInfo.action 28258 ms {"request":{"delta":28258,"pctg":100,"start":1241178083584,"stop":1241178111842,"remainder":30,"children":[
  {"validateUserInput":{"delta":15129,"pctg":53.53882086488782,"start":1241178083588,"stop":1241178098717,"remainder":10197,"children":[
    {"segment":{"delta":0,"pctg":0,"start":1241178092573,"stop":1241178092573}},
    {"fetch":{"delta":4932,"pctg":32.59964306960143,"start":1241178087711,"stop":1241178092643,"remainder":4406,"children":[
      {"fetch[0]":{"delta":85,"pctg":1.7234387672343876,"start":1241178087711,"stop":1241178087796,"remainder":0,"children":[
        {"adjust":{"delta":0,"pctg":0,"start":1241178087711,"stop":1241178087711}},
        {"ginsu":{"delta":0,"pctg":0,"start":1241178087711,"stop":1241178087711}},
        {"build in clause":{"delta":0,"pctg":0,"start":1241178087711,"stop":1241178087711}},
        {"slice":{"delta":85,"pctg":100,"start":1241178087711,"stop":1241178087796,"remainder":0,"children":[
          {"slice[0]":{"delta":85,"pctg":100,"start":1241178087711,"stop":1241178087796,"remainder":0,"children":[
            {"execute":{"delta":85,"pctg":100,"start":1241178087711,"stop":1241178087796}},
            {"unslice":{"delta":0,"pctg":0,"start":1241178087796,"stop":1241178087796}}]}}]}},
        {"unmap by iaId":{"delta":0,"pctg":0,"start":1241178087796,"stop":1241178087796}}]}},
      {"fetch[1]":{"delta":54,"pctg":1.094890510948905,"start":1241178087823,"stop":1241178087877,"remainder":0,"children":[
        {"adjust":{"delta":0,"pctg":0,"start":1241178087823,"stop":1241178087823}},
        {"ginsu":{"delta":0,"pctg":0,"start":1241178087823,"stop":1241178087823}},
        {"build in clause":{"delta":0,"pctg":0,"start":1241178087823,"stop":1241178087823}},
        {"slice":{"delta":54,"pctg":100,"start":1241178087823,"stop":1241178087877,"remainder":0,"children":[
          {"slice[0]":{"delta":54,"pctg":100,"start":1241178087823,"stop":1241178087877,"remainder":0,"children":[
            {"execute":{"delta":54,"pctg":100,"start":1241178087823,"stop":1241178087877}},
            {"unslice":{"delta":0,"pctg":0,"start":1241178087877,"stop":1241178087877}}]}}]}},
        {"unmap by iaId":{"delta":0,"pctg":0,"start":1241178087877,"stop":1241178087877}}]}},
      {"fetch[2]":{"delta":211,"pctg":4.278183292781833,"start":1241178087910,"stop":1241178088121,"remainder":0,"children":[
        {"adjust":{"delta":0,"pctg":0,"start":1241178087910,"stop":1241178087910}},
        {"ginsu":{"delta":0,"pctg":0,"start":1241178087910,"stop":1241178087910}},
        {"build in clause":{"delta":0,"pctg":0,"start":1241178087910,"stop":1241178087910}},
        {"slice":{"delta":211,"pctg":100,"start":1241178087910,"stop":1241178088121,"remainder":0,"children":[
          {"slice[0]":{"delta":211,"pctg":100,"start":1241178087910,"stop":1241178088121,"remainder":0,"children":[
            {"execute":{"delta":211,"pctg":100,"start":1241178087910,"stop":1241178088121}},
            {"unslice":{"delta":0,"pctg":0,"start":1241178088121,"stop":1241178088121}}]}}]}},
        {"unmap by iaId":{"delta":0,"pctg":0,"start":1241178088121,"stop":1241178088121}}]}},
      {"fetch[3]":{"delta":65,"pctg":1.3179237631792378,"start":1241178088156,"stop":1241178088221,"remainder":0,"children":[
        {"adjust":{"delta":0,"pctg":0,"start":1241178088156,"stop":1241178088156}},
        {"ginsu":{"delta":0,"pctg":0,"start":1241178088156,"stop":1241178088156}},
        {"build in clause":{"delta":0,"pctg":0,"start":1241178088156,"stop":1241178088156}},
        {"slice":{"delta":65,"pctg":100,"start":1241178088156,"stop":1241178088221,"remainder":0,"children":[
          {"slice[0]":{"delta":65,"pctg":100,"start":1241178088156,"stop":1241178088221,"remainder":0,"children":[
            {"execute":{"delta":65,"pctg":100,"start":1241178088156,"stop":1241178088221}},
            {"unslice":{"delta":0,"pctg":0,"start":1241178088221,"stop":1241178088221}}]}}]}},
        {"unmap by iaId":{"delta":0,"pctg":0,"start":1241178088221,"stop":1241178088221}}]}},
      {"fetch[4]":{"delta":41,"pctg":0.8313057583130575,"start":1241178088224,"stop":1241178088265,"remainder":0,"children":[
        {"adjust":{"delta":0,"pctg":0,"start":1241178088224,"stop":1241178088224}},
        {"ginsu":{"delta":0,"pctg":0,"start":1241178088224,"stop":1241178088224}},
        {"build in clause":{"delta":0,"pctg":0,"start":1241178088224,"stop":1241178088224}},
        {"slice":{"delta":41,"pctg":100,"start":1241178088224,"stop":1241178088265,"remainder":0,"children":[
          {"slice[0]":{"delta":41,"pctg":100,"start":1241178088224,"stop":1241178088265,"remainder":0,"children":[
            {"execute":{"delta":41,"pctg":100,"start":1241178088224,"stop":1241178088265}},
            {"unslice":{"delta":0,"pctg":0,"start":1241178088265,"stop":1241178088265}}]}}]}},
        {"unmap by iaId":{"delta":0,"pctg":0,"start":1241178088265,"stop":1241178088265}}]}},
      {"fetch[5]":{"delta":70,"pctg":1.419302514193025,"start":1241178092573,"stop":1241178092643,"remainder":0,"children":[
        {"adjust":{"delta":0,"pctg":0,"start":1241178092573,"stop":1241178092573}},
        {"ginsu":{"delta":0,"pctg":0,"start":1241178092573,"stop":1241178092573}},
        {"build in clause":{"delta":0,"pctg":0,"start":1241178092573,"stop":1241178092573}},
        {"slice":{"delta":70,"pctg":100,"start":1241178092573,"stop":1241178092643,"remainder":0,"children":[
          {"slice[0]":{"delta":70,"pctg":100,"start":1241178092573,"stop":1241178092643,"remainder":0,"children":[
            {"execute":{"delta":70,"pctg":100,"start":1241178092573,"stop":1241178092643}},
            {"unslice":{"delta":0,"pctg":0,"start":1241178092643,"stop":1241178092643}}]}}]}},
        {"unmap by iaId":{"delta":0,"pctg":0,"start":1241178092643,"stop":1241178092643}}]}}]}},
    {"datum-convert":{"delta":0,"deltaMean":0,"count":6,"deltaStddev":0,"start":1241178087796,"stop":1241178092643,"pctg":0}}]}},
  {"executeInner":{"delta":13099,"pctg":46.35501450916555,"start":1241178098717,"stop":1241178111816}},
  {"renderJson":{"delta":0,"pctg":0,"start":1241178111816,"stop":1241178111816}}]}}

was it a single server?  was it a group?  what was the time frame?  how long did the quan tab itself take?  more useful information would be nice.

Misc notes:

- Assumption: this is slow because there's a ton of quan data to look through (106 servers on this box). 

- We've looked at this query before. Leith suggested maybe breaking out to a temp table and do a join against that.

- Maybe UI should put up spinner or other cue that we're doing work

- Rumor has it load time reduced to 5 or 10 secs after Diego moved MEM repo to another system (Diego? Please confirm)

- Note to Diego: would save a lot of time if you can paste in Explain of the responsible query

Gary:

* Even though I have 106 servers there, I only have about 55 (+- 3) servers online at all times.

I first deployed 52 servers, monitored them for a few weeks, and then I stopped all of them and started monitoring 52 *new* servers (using mockload to fireup more events and have busier graphs)

* About using a tmp table, does anyone want to try this? you can give me the query and I can run it, or I can give you access to the repository

* UI -> we do see on the browser that the page is still loading, it would be nice to have a spinning thing, but I wouldn't spend too much time on it.

* Load time went down to about 5-6 seconds running the repo on a different box.

* Do you still need the explain ? (I  thought I pasted it, but I did not.

Gary Whizin writes: 
* UI should put up a spinner or other indication that work is taking place
* Support & docs should advise large sites to host repository on separate box if performance is slow (in this case, shrunk from 28 seconds to 5 secs for 100+ servers all with query analyzer data)

Josh Sled writes: 
there's no way a spinner is P2 ... setting P4, please adjust if necessary.

Josh Sled writes: 
revno: 7388
revision-id: jsled@asynchronous.org-20090721213344-r016slhgtayrsyq6
parent: jsled@asynchronous.org-20090721200535-4mevimqnpjfz56w1
committer: Josh Sled <jsled@asynchronous.org>
branch nick: local
timestamp: Tue 2009-07-21 17:33:44 -0400
message:
  EM-3237, Bug#44601: add a nifty loading screen to the QuerySummaryInfo popup

Bill Weber writes: 
patch available in builds >= 2.1.0.1080

Diego Medina writes: 
Verified fixed  on 2.1.0.1080

An entry was added to the 2.1.0 changelog:

In Enterprise Dashboard, clicking on a query listed on the Query Analyzer page resulted in a delay of around 28 seconds before the popup was displayed.