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

[1 May 2009 12:00] Diego Medina
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
[1 May 2009 12:01] Diego Medina
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}}]}}
[1 May 2009 15:05] Darren Oldag
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.
[14 May 2009 16:53] Gary Whizin
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
[14 May 2009 17:07] Diego Medina
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.
[7 Jul 2009 19:22] Enterprise Tools JIRA Robot
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)
[8 Jul 2009 21:56] Enterprise Tools JIRA Robot
Josh Sled writes: 
there's no way a spinner is P2 ... setting P4, please adjust if necessary.
[21 Jul 2009 21:40] Enterprise Tools JIRA Robot
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
[23 Jul 2009 22:41] Enterprise Tools JIRA Robot
Bill Weber writes: 
patch available in builds >= 2.1.0.1080
[27 Jul 2009 22:15] Enterprise Tools JIRA Robot
Diego Medina writes: 
Verified fixed  on 2.1.0.1080
[28 Jul 2009 13:02] Tony Bedford
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.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.065 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.