Adapt to collect stage information
authorSimon J Mudd <sjmudd@pobox.com>
Wed, 14 Jan 2015 22:03:25 +0000 (23:03 +0100)
committerSimon J Mudd <sjmudd@pobox.com>
Wed, 14 Jan 2015 22:03:25 +0000 (23:03 +0100)
p_s/events_stages_summary_global_by_event_name/private.go [new file with mode: 0644]
p_s/events_stages_summary_global_by_event_name/public.go [new file with mode: 0644]
p_s/setup_instruments/setup_instruments.go
state/state.go

diff --git a/p_s/events_stages_summary_global_by_event_name/private.go b/p_s/events_stages_summary_global_by_event_name/private.go
new file mode 100644 (file)
index 0000000..51028b6
--- /dev/null
@@ -0,0 +1,188 @@
+package events_stages_summary_global_by_event_name
+
+import (
+       "database/sql"
+       "fmt"
+       "log"
+       "sort"
+       "strings"
+
+       "github.com/sjmudd/pstop/lib"
+)
+
+/**************************************************************************
+
+root@localhost [performance_schema]> show create table  events_stages_summary_global_by_event_name\G
+*************************** 1. row ***************************
+       Table: events_stages_summary_global_by_event_name
+Create Table: CREATE TABLE `events_stages_summary_global_by_event_name` (
+  `EVENT_NAME` varchar(128) NOT NULL,
+  `COUNT_STAR` bigint(20) unsigned NOT NULL,
+  `SUM_TIMER_WAIT` bigint(20) unsigned NOT NULL,
+  `MIN_TIMER_WAIT` bigint(20) unsigned NOT NULL,
+  `AVG_TIMER_WAIT` bigint(20) unsigned NOT NULL,
+  `MAX_TIMER_WAIT` bigint(20) unsigned NOT NULL
+) ENGINE=PERFORMANCE_SCHEMA DEFAULT CHARSET=utf8
+1 row in set (0.00 sec)
+
+**************************************************************************/
+
+type table_row struct {
+       EVENT_NAME     string
+       COUNT_STAR     uint64
+       SUM_TIMER_WAIT uint64
+}
+
+type table_rows []table_row
+
+func select_rows(dbh *sql.DB) table_rows {
+       var t table_rows
+
+       lib.Logger.Println("events_stages_summary_global_by_event_name.select_rows()")
+       // we collect all information even if it's mainly empty as we may reference it later
+       sql := "SELECT EVENT_NAME, COUNT_STAR, SUM_TIMER_WAIT FROM events_stages_summary_global_by_event_name WHERE SUM_TIMER_WAIT > 0"
+
+       rows, err := dbh.Query(sql)
+       if err != nil {
+               log.Fatal(err)
+       }
+       defer rows.Close()
+
+       for rows.Next() {
+               var r table_row
+               if err := rows.Scan(
+                       &r.EVENT_NAME,
+                       &r.COUNT_STAR,
+                       &r.SUM_TIMER_WAIT); err != nil {
+                       log.Fatal(err)
+               }
+               t = append(t, r)
+       }
+       if err := rows.Err(); err != nil {
+               log.Fatal(err)
+       }
+       lib.Logger.Println("recovered", len(t), "row(s):")
+       lib.Logger.Println(t)
+
+       return t
+}
+
+// if the data in t2 is "newer", "has more values" than t then it needs refreshing.
+// check this by comparing totals.
+func (t table_rows) needs_refresh(t2 table_rows) bool {
+       my_totals := t.totals()
+       t2_totals := t2.totals()
+
+       return my_totals.SUM_TIMER_WAIT > t2_totals.SUM_TIMER_WAIT
+}
+
+func (t table_rows) totals() table_row {
+       var totals table_row
+       totals.EVENT_NAME = "Totals"
+
+       for i := range t {
+               totals.add(t[i])
+       }
+
+       return totals
+}
+
+func (this *table_row) name() string {
+       return this.EVENT_NAME
+}
+
+func (r *table_row) pretty_name() string {
+       s := r.name()
+       if len(s) > 30 {
+               s = s[:29]
+       }
+       return s
+}
+
+func (this *table_row) add(other table_row) {
+       this.SUM_TIMER_WAIT += other.SUM_TIMER_WAIT
+       this.COUNT_STAR += other.COUNT_STAR
+}
+
+// subtract the countable values in one row from another
+func (this *table_row) subtract(other table_row) {
+       // check for issues here (we have a bug) and log it
+       // - this situation should not happen so there's a logic bug somewhere else
+       if this.SUM_TIMER_WAIT >= other.SUM_TIMER_WAIT {
+               this.SUM_TIMER_WAIT -= other.SUM_TIMER_WAIT
+               this.COUNT_STAR -= other.COUNT_STAR
+       } else {
+               lib.Logger.Println("WARNING: table_row.subtract() - subtraction problem! (not subtracting)")
+               lib.Logger.Println("this=", this)
+               lib.Logger.Println("other=", other)
+       }
+}
+
+func (t table_rows) Len() int      { return len(t) }
+func (t table_rows) Swap(i, j int) { t[i], t[j] = t[j], t[i] }
+
+// sort by value (descending) but also by "name" (ascending) if the values are the same
+func (t table_rows) Less(i, j int) bool {
+       return (t[i].SUM_TIMER_WAIT > t[j].SUM_TIMER_WAIT) ||
+               ((t[i].SUM_TIMER_WAIT == t[j].SUM_TIMER_WAIT) && (t[i].EVENT_NAME < t[j].EVENT_NAME))
+}
+
+func (t table_rows) Sort() {
+       sort.Sort(t)
+}
+
+// remove the initial values from those rows where there's a match
+// - if we find a row we can't match ignore it
+func (this *table_rows) subtract(initial table_rows) {
+       initial_by_name := make(map[string]int)
+
+       // iterate over rows by name
+       for i := range initial {
+               initial_by_name[initial[i].name()] = i
+       }
+
+       for i := range *this {
+               this_name := (*this)[i].name()
+               if _, ok := initial_by_name[this_name]; ok {
+                       initial_index := initial_by_name[this_name]
+                       (*this)[i].subtract(initial[initial_index])
+               }
+       }
+}
+
+func (r *table_row) headings() string {
+       return fmt.Sprintf("%-30s %10s %6s %6s", "Stage Name", "Latency", "%", "Count")
+}
+
+// generate a printable result
+func (r *table_row) row_content(totals table_row) string {
+       name := r.pretty_name()
+       if r.COUNT_STAR == 0 && name != "Totals" {
+               name = ""
+       }
+
+       return fmt.Sprintf("%-30s|%10s %6s %6s",
+               name,
+               lib.FormatTime(r.SUM_TIMER_WAIT),
+               lib.FormatPct(lib.MyDivide(r.SUM_TIMER_WAIT, totals.SUM_TIMER_WAIT)),
+               lib.FormatAmount(r.COUNT_STAR))
+}
+
+// describe a whole row
+func (r table_row) String() string {
+       return fmt.Sprintf("%-30s %10s %10s",
+               r.pretty_name(),
+               lib.FormatTime(r.SUM_TIMER_WAIT),
+               lib.FormatAmount(r.COUNT_STAR))
+}
+
+// describe a whole table
+func (t table_rows) String() string {
+       s := make([]string, len(t))
+
+       for i := range t {
+               s = append(s, t[i].String())
+       }
+
+       return strings.Join(s, "\n")
+}
diff --git a/p_s/events_stages_summary_global_by_event_name/public.go b/p_s/events_stages_summary_global_by_event_name/public.go
new file mode 100644 (file)
index 0000000..39777f3
--- /dev/null
@@ -0,0 +1,141 @@
+package events_stages_summary_global_by_event_name
+
+import (
+       "database/sql"
+       "fmt"
+       "time"
+
+       "github.com/sjmudd/pstop/lib"
+       "github.com/sjmudd/pstop/p_s"
+)
+
+/*
+
+root@localhost [performance_schema]> select * from events_stages_summary_global_by_event_name where sum_timer_wait > 0;
++--------------------------------+------------+----------------+----------------+----------------+----------------+
+| EVENT_NAME                     | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
++--------------------------------+------------+----------------+----------------+----------------+----------------+
+| stage/sql/After create         |          3 |       21706000 |         558000 |        7235000 |       11693000 |
+| stage/sql/checking permissions |       5971 |    92553236000 |         406000 |       15500000 |    12727728000 |
+| stage/sql/cleaning up          |       6531 |     4328103000 |         154000 |         662000 |       23464000 |
+| stage/sql/closing tables       |       4281 |    18303106000 |         118000 |        4275000 |       71505000 |
+| stage/sql/Creating sort index  |          2 |    31300648000 |    14183237000 |    15650324000 |    17117411000 |
+| stage/sql/creating table       |          2 |   138276471000 |    64077127000 |    69138235000 |    74199344000 |
+| stage/sql/end                  |       4254 |     9940694000 |         220000 |        2336000 |       42683000 |
+| stage/sql/executing            |       1256 |   252300800000 |         151000 |      200876000 |    59564212000 |
+| stage/sql/freeing items        |       3733 |    83966405000 |        5341000 |       22493000 |     2527549000 |
+| stage/sql/init                 |       4256 |    63836793000 |        1990000 |       14999000 |     7656920000 |
+| stage/sql/Opening tables       |       6002 |  1489653915000 |        1411000 |      248192000 |   216300236000 |
+| stage/sql/optimizing           |       1257 |  2685426016000 |         255000 |     2136377000 |  2656149827000 |
+| stage/sql/preparing            |       1166 |     8626237000 |        1666000 |        7398000 |       91804000 |
+| stage/sql/query end            |       4280 |    37299265000 |         411000 |        8714000 |    12018400000 |
+| stage/sql/removing tmp table   |       1187 |    11890909000 |        1838000 |       10017000 |     2365358000 |
+| stage/sql/Sending data         |       1165 |  3071893676000 |        2925000 |     2636818000 |    63354201000 |
+| stage/sql/Sorting result       |          2 |        4128000 |        1930000 |        2064000 |        2198000 |
+| stage/sql/statistics           |       1166 |    26655651000 |        2078000 |       22860000 |     8446818000 |
+| stage/sql/System lock          |       4263 |  1901250693000 |         584000 |      445988000 |  1651181465000 |
+| stage/sql/update               |          4 |     8246608000 |       78145000 |     2061652000 |     7597263000 |
+| stage/sql/updating             |       2994 |  1608420140000 |      285867000 |      537214000 |    15651495000 |
+| stage/sql/starting             |       6532 |   364087027000 |        2179000 |       55738000 |    23420395000 |
++--------------------------------+------------+----------------+----------------+----------------+----------------+
+22 rows in set (0.01 sec)
+
+*/
+
+// public view of object
+type Object struct {
+       p_s.RelativeStats
+       p_s.InitialTime
+       initial table_rows // initial data for relative values
+       current table_rows // last loaded values
+       results table_rows // results (maybe with subtraction)
+       totals  table_row  // totals of results
+}
+
+// Collect() collects data from the db, updating initial
+// values if needed, and then subtracting initial values if we want
+// relative values, after which it stores totals.
+func (t *Object) Collect(dbh *sql.DB) {
+       start := time.Now()
+       t.current = select_rows(dbh)
+       lib.Logger.Println("t.current collected", len(t.current), "row(s) from SELECT")
+
+       if len(t.initial) == 0 && len(t.current) > 0 {
+               lib.Logger.Println("t.initial: copying from t.current (initial setup)")
+               t.initial = make(table_rows, len(t.current))
+               copy(t.initial, t.current)
+       }
+
+       // check for reload initial characteristics
+       if t.initial.needs_refresh(t.current) {
+               lib.Logger.Println("t.initial: copying from t.current (data needs refreshing)")
+               t.initial = make(table_rows, len(t.current))
+               copy(t.initial, t.current)
+       }
+
+       t.make_results()
+
+       // lib.Logger.Println( "t.initial:", t.initial )
+       // lib.Logger.Println( "t.current:", t.current )
+       lib.Logger.Println("t.initial.totals():", t.initial.totals())
+       lib.Logger.Println("t.current.totals():", t.current.totals())
+       // lib.Logger.Println("t.results:", t.results)
+       // lib.Logger.Println("t.totals:", t.totals)
+       lib.Logger.Println("Table_io_waits_summary_by_table.Collect() END, took:", time.Duration(time.Since(start)).String())
+}
+
+func (t *Object) Headings() string {
+       return t.totals.headings()
+}
+
+func (t Object) RowContent(max_rows int) []string {
+       rows := make([]string, 0, max_rows)
+
+       for i := range t.results {
+               if i < max_rows {
+                       rows = append(rows, t.results[i].row_content(t.totals))
+               }
+       }
+
+       return rows
+}
+
+func (t Object) EmptyRowContent() string {
+       var e table_row
+
+       return e.row_content(e)
+}
+
+func (t Object) TotalRowContent() string {
+       return t.totals.row_content(t.totals)
+}
+
+func (t Object) Description() string {
+       count := t.count_rows()
+       return fmt.Sprintf("Latency by SQL stage (events_stages_summary_global_by_event_name) %d rows", count)
+}
+
+func (t *Object) SyncReferenceValues() {
+}
+
+func (t *Object) make_results() {
+       // lib.Logger.Println( "- t.results set from t.current" )
+       t.results = make(table_rows, len(t.current))
+       copy(t.results, t.current)
+       if t.WantRelativeStats() {
+               t.results.subtract(t.initial)
+       }
+
+       t.results.Sort()
+       t.totals = t.results.totals()
+}
+
+func (t Object) count_rows() int {
+       var count int
+       for row := range t.results {
+               if t.results[row].SUM_TIMER_WAIT > 0 {
+                       count++
+               }
+       }
+       return count
+}
index 595e75a..34c30fe 100644 (file)
@@ -8,7 +8,8 @@ import (
 )
 
 // Error 1142: UPDATE command denied to user
-const UPDATE_FAILED = "Error 1142"
+// Error 1290: The MySQL server is running with the --read-only option so it cannot execute this statement
+var EXPECTED_UPDATE_ERRORS = []string { "Error 1142", "Error 1290" }
 
 type setup_instruments_row struct {
        NAME    string
@@ -63,17 +64,23 @@ func (si *SetupInstruments) EnableMutexMonitoring(dbh *sql.DB) {
                if _, err := dbh.Exec(sql); err == nil {
                        si.update_succeeded = true
                } else {
-                       if err.Error()[0:10] != UPDATE_FAILED {
+                       found_expected := false
+                       for i := range EXPECTED_UPDATE_ERRORS {
+                               if err.Error()[0:10] == EXPECTED_UPDATE_ERRORS[i] {
+                                       found_expected = true
+                                       break
+                               }
+                       }
+                       if ! found_expected {
                                log.Fatal(err)
                        }
+                       lib.Logger.Println( "Insufficient privileges to UPDATE setup_instruments: " + err.Error() )
                        break
                }
                count++
        }
        if si.update_succeeded {
                lib.Logger.Println(count, "rows changed in p_s.setup_instruments")
-       } else {
-               lib.Logger.Println( "Insufficient privileges to UPDATE setup_instruments: " . err.String() )
        }
 }
 
index f1fbe88..33a86ea 100644 (file)
@@ -12,6 +12,7 @@ import (
        "github.com/sjmudd/pstop/i_s"
        "github.com/sjmudd/pstop/lib"
        ewsgben "github.com/sjmudd/pstop/p_s/events_waits_summary_global_by_event_name"
+       essgben "github.com/sjmudd/pstop/p_s/events_stages_summary_global_by_event_name"
        fsbi "github.com/sjmudd/pstop/p_s/file_summary_by_instance"
        "github.com/sjmudd/pstop/p_s/ps_table"
        "github.com/sjmudd/pstop/p_s/setup_instruments"
@@ -32,6 +33,7 @@ const (
        showLocks   = iota
        showUsers   = iota
        showMutex   = iota
+       showStages  = iota
 )
 
 type State struct {
@@ -44,6 +46,7 @@ type State struct {
        tiwsbt              tiwsbt.Table_io_waits_summary_by_table
        tlwsbt              ps_table.Tabler // tlwsbt.Table_lock_waits_summary_by_table
        ewsgben             ps_table.Tabler // ewsgben.Events_waits_summary_global_by_event_name
+       essgben             ps_table.Tabler // essgben.Events_stages_summary_global_by_event_name
        users               i_s.Processlist
        screen              screen.TermboxScreen
        show                Show
@@ -65,6 +68,7 @@ func (state *State) Setup(dbh *sql.DB) {
        state.fsbi = fsbi.NewFileSummaryByInstance(variables)
        state.tlwsbt = new(tlwsbt.Table_lock_waits_summary_by_table)
        state.ewsgben = new(ewsgben.Table_events_waits_summary_global_by_event_name)
+       state.essgben = new(essgben.Object)
 
        state.want_relative_stats = true // we show info from the point we start collecting data
        state.fsbi.SetWantRelativeStats(state.want_relative_stats)
@@ -75,6 +79,8 @@ func (state *State) Setup(dbh *sql.DB) {
        state.tiwsbt.SetNow()
        state.users.SetWantRelativeStats(state.want_relative_stats)   // ignored
        state.users.SetNow()                                          // ignored
+       state.essgben.SetWantRelativeStats(state.want_relative_stats)
+       state.essgben.SetNow()
        state.ewsgben.SetWantRelativeStats(state.want_relative_stats) // ignored
        state.ewsgben.SetNow()                                        // ignored
 
@@ -117,6 +123,7 @@ func (state *State) SyncReferenceValues() {
        state.fsbi.SyncReferenceValues()
        state.tlwsbt.SyncReferenceValues()
        state.tiwsbt.SyncReferenceValues()
+       state.essgben.SyncReferenceValues()
        lib.Logger.Println("state.SyncReferenceValues() took", time.Duration(time.Since(start)).String())
 }
 
@@ -142,6 +149,8 @@ func (state *State) Collect() {
                state.users.Collect(state.dbh)
        case showMutex:
                state.ewsgben.Collect(state.dbh)
+       case showStages:
+               state.essgben.Collect(state.dbh)
        }
        lib.Logger.Println("state.Collect() took", time.Duration(time.Since(start)).String())
 }
@@ -177,7 +186,7 @@ func (state State) Help() bool {
        return state.help
 }
 
-// states go: showLatency -> showOps -> showIO -> showLocks -> showUsers -> showMutex
+// states go: showLatency -> showOps -> showIO -> showLocks -> showUsers -> showMutex -> showStages
 
 // display the output according to the mode we are in
 func (state *State) Display() {
@@ -196,6 +205,8 @@ func (state *State) Display() {
                        state.displayUsers()
                case showMutex:
                        state.displayMutex()
+               case showStages:
+                       state.displayStages()
                }
        }
 }
@@ -214,7 +225,7 @@ func (state *State) fix_latency_setting() {
 // change to the previous display mode
 func (state *State) DisplayPrevious() {
        if state.show == showLatency {
-               state.show = showMutex
+               state.show = showStages
        } else {
                state.show--
        }
@@ -225,7 +236,7 @@ func (state *State) DisplayPrevious() {
 
 // change to the next display mode
 func (state *State) DisplayNext() {
-       if state.show == showMutex {
+       if state.show == showStages {
                state.show = showLatency
        } else {
                state.show++
@@ -257,6 +268,8 @@ func (state State) displayLine0() {
                        initial = state.tlwsbt.Last()
                case showUsers:
                        initial = state.users.Last()
+               case showStages:
+                       initial = state.essgben.Last()
                case showMutex:
                        initial = state.ewsgben.Last()
                default:
@@ -286,6 +299,8 @@ func (state State) displayDescription() {
                description = state.users.Description()
        case showMutex:
                description = state.ewsgben.Description()
+       case showStages:
+               description = state.essgben.Description()
        }
 
        state.screen.PrintAt(0, 1, description)
@@ -411,6 +426,31 @@ func (state *State) displayMutex() {
        state.screen.BoldPrintAt(0, state.screen.Height()-1, state.ewsgben.TotalRowContent())
 }
 
+func (state *State) displayStages() {
+       state.screen.BoldPrintAt(0, 2, state.essgben.Headings())
+
+       // print out the data
+       max_rows := state.screen.Height() - 3
+       row_content := state.essgben.RowContent(max_rows)
+
+       // print out rows
+       for k := range row_content {
+               y := 3 + k
+               state.screen.PrintAt(0, y, row_content[k])
+       }
+       // print out empty rows
+       for k := len(row_content); k < (state.screen.Height() - 3); k++ {
+               y := 3 + k
+               if y < state.screen.Height()-1 {
+                       state.screen.PrintAt(0, y, state.essgben.EmptyRowContent())
+               }
+       }
+
+       // print out the totals at the bottom
+       state.screen.BoldPrintAt(0, state.screen.Height()-1, state.essgben.TotalRowContent())
+}
+
+
 // do we want to show all p_s data?
 func (state State) WantRelativeStats() bool {
        return state.want_relative_stats