From 23d4cb81352e26f3b76b41858988f8aca5797f41 Mon Sep 17 00:00:00 2001 From: Simon J Mudd Date: Wed, 14 Jan 2015 23:03:25 +0100 Subject: [PATCH] Adapt to collect stage information --- .../private.go | 188 +++++++++++++++++++++ .../public.go | 141 ++++++++++++++++ p_s/setup_instruments/setup_instruments.go | 15 +- state/state.go | 46 ++++- 4 files changed, 383 insertions(+), 7 deletions(-) create mode 100644 p_s/events_stages_summary_global_by_event_name/private.go create mode 100644 p_s/events_stages_summary_global_by_event_name/public.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 index 0000000..51028b6 --- /dev/null +++ b/p_s/events_stages_summary_global_by_event_name/private.go @@ -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 index 0000000..39777f3 --- /dev/null +++ b/p_s/events_stages_summary_global_by_event_name/public.go @@ -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 +} diff --git a/p_s/setup_instruments/setup_instruments.go b/p_s/setup_instruments/setup_instruments.go index 595e75a..34c30fe 100644 --- a/p_s/setup_instruments/setup_instruments.go +++ b/p_s/setup_instruments/setup_instruments.go @@ -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() ) } } diff --git a/state/state.go b/state/state.go index f1fbe88..33a86ea 100644 --- a/state/state.go +++ b/state/state.go @@ -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 -- 2.7.4