Real-time Performance Info with mytop Background

mytop is an open source tool that provides real-time performance statistics and query information for MySQL. It’s named after and inspired by the Unix operating system tool, top.

If you’re completing this procedure in our lab, we’ve pre-installed mytop for you. Otherwise, the install directions are in the README on Github.

The most comprehensive usage documentation is in the man page, which you can access with man mytop on a server that has mytop installed, or read on Github.

Generate a Small Workload on MySQL

First, we’re going to create some load on the server, since our lab server doesn’t have any “real” traffic. If you’re running mytop on an existing server, skip ahead to step 2.

SSH to mytop.example.com and set up a long-running mysqlslap background job.

mytop ~ $ mysqlslap --auto-generate-sql --number-of-queries=1000000 &
[1] 2776
mytop ~ $

This starts mysqlslap running a million INSERTs and DELETEs against a database and table it generates automatically.

In the sample output above, mysqlslap is running in the background as job 1, process id 2776.

View a Small Workload with mytop

Now run mytop to view realtime MySQL performance.

mytop ~ $ mytop

The output will update every 5 seconds, the example below is after it has had a few iterations to collect data.

Here’s a complete screenshot:

MySQL on localhost (5.5.31)                                                       up 0+00:56:34 [19:44:54]
 Queries: 55.2k  qps:   17 Slow:     0.0         Se/In/Up/De(%):    45/55/00/00
             qps now:   18 Slow qps: 0.0  Threads:    3 (   2/   0) 44/53/00/00
 Key Efficiency: 90.0%  Bps in/out:  1.8k/ 4.8M   Now in/out:  1.8k/ 1.5M

      Id      User         Host/IP         DB      Time    Cmd Query or State
       --      ----         -------         --      ----    --- ----------
       49      root       localhost  mysqlslap         0  Query INSERT INTO t1 VALUES (95275444,'bNIrBDBl8
       50      root       localhost       test         0  Query show full processlist
       48      root       localhost  mysqlslap        49  Sleep

Let’s break that down line-by-line. In the first line:

MySQL on localhost (5.5.31)                                                       up 0+00:56:34 [19:44:54]

localhost is the host name we’re connected to.

5.5.31 is the MySQL version on that server.

up 0+00:56:34 is the MySQL process’s uptime, in day+hour:minute:second format.

19:44:54 is the current time (our lab servers use UTC).


In the second line, all statistics are cumulative since server startup.

Queries: 55.2k  qps:   17 Slow:     0.0         Se/In/Up/De(%):    45/55/00/00

Queries: 55.2k the server has processed more than 55,200 queries.

qps: 17 the server averages 17 queries per second.

Slow: 0.0 the server averages 0 slow queries per second. (This mysqlslap configuration runs lots of short, simple queries.)

45/55/00/00 of all the traffic this server has handled, 45% of queries are SELECTs, 55% INSERTs, 0% UPDATEs, and 0% DELETEs.


In the third line, all statistics are only from the last sample (5 seconds, by default).

qps now:   18 Slow qps: 0.0  Threads:    3 (   2/   0) 44/53/00/00

qps now: 18 In the last 5 seconds, the server averaged 18 queries per second.

Slow qps: 0.0 the server averaged 0 slow queries per second.

Threads 3 ( 2/ 0) There are 3 connected threads, 2 are active (one is sleeping), and there are 0 threads in the thread cache.

44/53/00/00 in this 5-second sample, 44% of queries were SELECTs, 53% were INSERTs.


In the fourth line:

Key Efficiency: 90.0%  Bps in/out:  1.8k/ 4.8M   Now in/out:  1.8k/ 1.5M

Key Efficiency: 90.0% 90% of keys are read from the buffer, not from disk.

Bps in/out: 1.8k/ 4.8M Since startup, MySQL has averaged 1.8kbps inbound traffic and 4.8Mbps outbound traffic.

Now in/out: 1.8k/ 1.5M In the last 5 seconds, MySQL has averaged 1.8kbps inbound traffic and 1.5Mbps outbound traffic.


The remainder of the output shows three active threads.

Id      User         Host/IP         DB      Time    Cmd Query or State
 --      ----         -------         --      ----    --- ----------
 49      root       localhost  mysqlslap         0  Query INSERT INTO t1 VALUES (95275444,'bNIrBDBl8
 50      root       localhost       test         0  Query show full processlist
 48      root       localhost  mysqlslap        49  Sleep

Thread 49 is mysqlslap inserting a value.

Thread 50 is mytop collecting this process table.

Thread 48 is sleeping (not processing a query, but still connected).

End the Small Workload

Press q to close mytop.

We used & to start mysqlslap as a background job. Look up the job number.

mytop ~ $ jobs
[1]+  Running                 mysqlslap --auto-generate-sql --number-of-queries=1000000 &

It’s listed as job 1, bring that job from the background to the foreground with fg

mytop ~ $ fg 1
mysqlslap --auto-generate-sql --number-of-queries=1000000

Stop mysqlslap by pressing control + c

^C
mytop ~ $
Generate a Large Workload

This will start a new mysqlslap load, but instead of running the million statements sequentially, it will start 10 threads in parallel.

mytop ~ $ mysqlslap --auto-generate-sql --concurrency=10 --number-of-queries=1000000 &
[1] 2997
mytop ~ $
View a Large Workload with mytop

Now start mytop again to watch the large workload. This time, we’ll specify that mytop should connect to the mysqlslap database, so we can look in depth at queries in the next step.

mytop ~ $ mytop --database mysqlslap

Here’s a screenshot after mytop has collected a few 5-second samples.

Notice that specifying the --database doesn’t change this view.

MySQL on localhost (5.5.31)                                             up 0+01:29:07 [21:42:06]
 Queries: 21.5k  qps:    4 Slow:     0.0         Se/In/Up/De(%):    45/55/00/00
             qps now:   43 Slow qps: 0.0  Threads:   12 (  11/   0) 45/55/00/00
 Key Efficiency: 90.0%  Bps in/out: 447.6/659.4k   Now in/out:  4.6k/14.8M

      Id      User         Host/IP         DB      Time    Cmd Query or State
       --      ----         -------         --      ----    --- ----------
       11      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       12      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       13      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       14      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       15      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       16      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       17      root       localhost  mysqlslap         0  Query INSERT INTO t1 VALUES (100669,'q
       18      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       19      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       20      root       localhost  mysqlslap         0  Query INSERT INTO t1 VALUES (100669,'q
       21      root       localhost       test         0  Query show full processlist
       10      root       localhost  mysqlslap        86  Sleep

What’s new in this run?

In the third line, 12 ( 11/ 0) summarizes the 12 connected threads, 11 active (one sleeping), and still 0 threads in the thread cache.

At the bottom, this screenshot happened to capture eight SELECT statements in progress, and just two INSERTs, although we can see in lines 2 and 3 that the blend since start and in this sample are both 45/55/00/00, meaning 45% SELECT and 55% INSERT.

Detailed View

Pick a query that looks interesting. From this screenshot, I’d like to see the complete INSERT query (not just what fits on screen).

MySQL on localhost (5.5.31)                                             up 0+01:29:07 [21:42:06]
 Queries: 21.5k  qps:    4 Slow:     0.0         Se/In/Up/De(%):    45/55/00/00
             qps now:   43 Slow qps: 0.0  Threads:   12 (  11/   0) 45/55/00/00
 Key Efficiency: 90.0%  Bps in/out: 447.6/659.4k   Now in/out:  4.6k/14.8M

      Id      User         Host/IP         DB      Time    Cmd Query or State
       --      ----         -------         --      ----    --- ----------
       11      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       12      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       13      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       14      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       15      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       16      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       17      root       localhost  mysqlslap         0  Query INSERT INTO t1 VALUES (100669,'q
       18      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       19      root       localhost  mysqlslap         0  Query SELECT intcol1,charcol1 FROM t1
       20      root       localhost  mysqlslap         0  Query INSERT INTO t1 VALUES (100669,'q
       21      root       localhost       test         0  Query show full processlist
       10      root       localhost  mysqlslap        86  Sleep

From the first column, I see that was running on thread id 20.

Press f then type the thread Id, for example 20 and press enter.

Thread 20 was executing following query:

INSERT INTO t1 VALUES (100669,'qMa5SuKo4M5OM7ldvisSc6WK9rsG9E8sSixocHdgfa5uiiNTGFxkDJ4EAwWC2e4NL1BpAgWiFRcp1zIH6F1BayPdmwphatwnmzdwgzWnQ6SRxmcvtd6JRYwEKdvuWr')

-- paused. press any key to resume or (e) to explain --

There’s no point running explain on this query, explaining INSERTs is not supported until MySQL 5.6 and as we see above, this server is running MySQL 5.5.31.

So press any other key, and choose a SELECT query:

MySQL on localhost (5.5.31)                                             up 0+02:03:25 [22:16:26]
 Queries: 56.8k  qps:    8 Slow:     0.0         Se/In/Up/De(%):    45/54/00/00
             qps now:   35 Slow qps: 0.0  Threads:   12 (  11/   0) 45/54/00/00
 Key Efficiency: 90.0%  Bps in/out: 847.0/ 5.0M   Now in/out:  3.6k/52.6M

      Id      User         Host/IP         DB      Time    Cmd Query or State
       --      ----         -------         --      ----    --- ----------
       25      root       localhost  mysqlslap         0  Query show full processlist
       11      root       localhost  mysqlslap         1  Sleep
       12      root       localhost  mysqlslap         1  Query SELECT intcol1,charcol1 FROM t1
       13      root       localhost  mysqlslap         1  Query SELECT intcol1,charcol1 FROM t1
       14      root       localhost  mysqlslap         1  Query SELECT intcol1,charcol1 FROM t1
       15      root       localhost  mysqlslap         1  Query SELECT intcol1,charcol1 FROM t1
       16      root       localhost  mysqlslap         1  Query SELECT intcol1,charcol1 FROM t1
       17      root       localhost  mysqlslap         1  Sleep
       18      root       localhost  mysqlslap         1  Query INSERT INTO t1 VALUES (73673339,
       19      root       localhost  mysqlslap         1  Sleep
       20      root       localhost  mysqlslap         1  Query SELECT intcol1,charcol1 FROM t1
       10      root       localhost  mysqlslap      2146  Sleep

Note that in the previous step, we connected mytop to the mysqlslap database, the same database this row indicates in the fourth column.

Press f, type the session Id you’ve chosen, then press enter.

Thread 12 was executing following query:

SELECT intcol1,charcol1 FROM t1

-- paused. press any key to resume or (e) to explain --

This time, press e and mytop will show you the EXPLAIN results for that query. Unfortunately the queries and the tables mysqlslap uses are both very boring, but using this with your production data will be much more interesting.

EXPLAIN SELECT intcol1,charcol1 FROM t1:

*** row 1 ***
          table:  t1
           type:  ALL
  possible_keys:  NULL
            key:  NULL
        key_len:  NULL
            ref:  NULL
           rows:  25916
          Extra:  NULL
-- paused. press any key to resume --
End the Large Workload

If you’re running this in our lab, you can just skip to the bottom of the page and press Release the Lab Servers and leave the clean up to us.

Press q to close mytop.

Look up mysqlslap‘s job number.

mytop ~ $ jobs
[1]+  Running                 mysqlslap --auto-generate-sql --concurrency=10 --number-of-queries=1000000 &

Bring job 1, to the foreground with fg

mytop ~ $ fg 1
mysqlslap --auto-generate-sql --concurrency=10 --number-of-queries=1000000

Stop mysqlslap by pressing control + c

^C
mytop ~ $

Source

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s