func containerCountOverlays(entries []chug.LogEntry) []analyzers.LineOverlay { lrps := Events{} tasks := Events{} for _, entry := range entries { if entry.Message == "garden-linux.garden-server.bulk_info.got-bulkinfo" { nTasks := 0.0 nLRPS := 0.0 handles := reflect.ValueOf(entry.Data["handles"]) for i := 0; i < handles.Len(); i += 1 { handle := handles.Index(i).Interface().(string) if len(handle) == 110 { nLRPS += 1 } if len(handle) == 69 { nTasks += 1 } } lrps = append(lrps, Event{T: entry.Timestamp, V: nLRPS}) tasks = append(tasks, Event{T: entry.Timestamp, V: nTasks}) } } return []analyzers.LineOverlay{ {lrps, viz.LineStyle(viz.Blue, 2)}, {tasks, viz.LineStyle(viz.Red, 2)}, } }
func GenerateEventDurationCommand() say.Command { var minT, maxT float64 var skipList string var blueEvent, redEvent string var outFile string var significantThreshold int var fs = &flag.FlagSet{} fs.Float64Var(&minT, "tmin", 0, "Min time") fs.Float64Var(&maxT, "tmax", 0, "Max time") fs.StringVar(&skipList, "skip", "", "Events to skip (comma delimited)") fs.StringVar(&blueEvent, "blue", "", "Events to use to generate blue markers") fs.StringVar(&redEvent, "red", "", "Events to use to generate red markers") fs.IntVar(&significantThreshold, "n", 2, "Minimum number of events required to make it onto the plot") fs.StringVar(&outFile, "o", "", "Output file") return say.Command{ Name: "event-duration", Description: "lager.log -- generate event duration plots", FlagSet: fs, Run: func(args []string) { if len(args) != 1 { say.Println(0, say.Red("please provide a lager file to read")) os.Exit(1) } markedEvents := map[string]plot.LineStyle{} if blueEvent != "" { markedEvents[blueEvent] = viz.LineStyle(viz.Blue, 1, viz.Dot) } if redEvent != "" { markedEvents[redEvent] = viz.LineStyle(viz.Red, 1, viz.Dot) } options := analyzers.SignificantEventsOptions{ MinX: minT, MaxX: maxT, MarkedEvents: markedEvents, } skips := strings.Split(skipList, ",") if outFile == "" { outFile = "out.png" } analyzeEventDurations(args[0], options, significantThreshold, skips, outFile) }, } }
func healthCheckTimeoutsFailedHealthMonitor(entries []chug.LogEntry) []analyzers.VerticalMarker { markers := []analyzers.VerticalMarker{} for _, entry := range entries { if entry.Message == "rep.event-consumer.operation-stream.executing-container-operation.ordinary-lrp-processor.process-reserved-container.run-container.containerstore-create.starting" { markers = append(markers, analyzers.VerticalMarker{T: entry.Timestamp, LineStyle: viz.LineStyle(viz.Blue, 1, viz.Dot)}) } if entry.Message == "rep.event-consumer.operation-stream.executing-container-operation.ordinary-lrp-processor.process-reserved-container.run-container.containerstore-run.node-run.monitor-run.timeout-step.timed-out" { markers = append(markers, analyzers.VerticalMarker{T: entry.Timestamp, LineStyle: viz.LineStyle(viz.Red, 2, viz.Dot)}) } if entry.Message == "rep.event-consumer.operation-stream.executing-container-operation.ordinary-lrp-processor.process-reserved-container.run-container.containerstore-run.node-run.monitor-run.run-step.failed-creating-process" { markers = append(markers, analyzers.VerticalMarker{T: entry.Timestamp, LineStyle: viz.LineStyle(viz.Red, 2, viz.Dash)}) } } return markers }
func analyzeSlowPWSTasks() { for _, run := range slowPWSTaskRuns { say.Println(0, say.Green(run.Name)) data, err := ioutil.ReadFile(config.DataDir("pws-slow-tasks", run.Name+".unified")) say.ExitIfError("couldn't read log file", err) entries := util.ChugLagerEntries(data) significantEvents := analyzers.ExtractSignificantEvents(entries) allow := map[string]bool{ "rep.auction-fetch-state.handling": true, "rep.container-metrics-reporter.tick.started": true, "rep.depot-client.run-container.creating-container-in-garden": true, "rep.depot-client.delete-container.destroy.started": true, "rep.depot-client.run-container.run.action.download-step.fetch-starting": true, "rep.depot-client.run-container.run.monitor-run.run-step.running": true, "rep.depot-client.run-container.run.run-step-process.step-finished-with-error": true, "rep.depot-client.run-container.run.setup.download-step.fetch-starting": true, } filteredSignificantEvents := analyzers.SignificantEvents{} for name, events := range significantEvents { if allow[name] { filteredSignificantEvents[name] = events } } filteredSignificantEvents.LogWithThreshold(0.2) options := analyzers.SignificantEventsOptions{ LineOverlays: containerCountOverlays(entries), } if !run.CliffTimestamp.IsZero() { options.MaxT = run.EndTimestamp.Add(time.Minute * 30) options.VerticalMarkers = []analyzers.VerticalMarker{ {T: run.CliffTimestamp, LineStyle: viz.LineStyle(viz.Red, 1, viz.Dash)}, {T: run.EndTimestamp, LineStyle: viz.LineStyle(viz.Black, 1, viz.Dash)}, } } analyzers.VisualizeSignificantEvents( filteredSignificantEvents, config.DataDir("pws-slow-tasks", run.Name+".png"), options, ) } }
func gardenStressTestFailedContainerCreates(entries []chug.LogEntry) []analyzers.VerticalMarker { markers := []analyzers.VerticalMarker{} for _, entry := range entries { if entry.Message == "rep.depot-client.run-container.failed-creating-container-in-garden" { markers = append(markers, analyzers.VerticalMarker{T: entry.Timestamp, LineStyle: viz.LineStyle(viz.Red, 1, viz.Dot)}) } } return markers }
func pwsSlowEvacuationFailedProcessOverlays(entries []chug.LogEntry) []analyzers.VerticalMarker { markers := []analyzers.VerticalMarker{} for _, entry := range entries { if entry.Message == "rep.depot-client.run-container.run.run-step-process.step-finished-with-error" { markers = append(markers, analyzers.VerticalMarker{T: entry.Timestamp, LineStyle: viz.LineStyle(viz.Red, 1, viz.Dot)}) } } return markers }
func analyzeGardenAUFSStressTests() { runs := []string{"diego-2.cell-z1.0"} //, "diego-1.cell-z1.0"} for _, run := range runs { data, err := ioutil.ReadFile(config.DataDir("garden-aufs-test", run+".unified")) say.ExitIfError("couldn't read log file", err) entries := util.ChugLagerEntries(data) significantEvents := analyzers.ExtractSignificantEvents(entries) // significantEvents.LogWithThreshold(0.2) allow := map[string]bool{ "garden-linux.loop-mounter.unmount.failed-to-unmount": true, "garden-linux.garden-server.create.creating": true, "rep.auction-fetch-state.handling": true, "rep.container-metrics-reporter.tick.started": true, "rep.depot-client.run-container.creating-container-in-garden": true, "rep.depot-client.delete-container.destroy.started": true, "rep.depot-client.run-container.run.action.download-step.fetch-starting": true, "rep.depot-client.run-container.run.monitor-run.run-step.running": true, "rep.depot-client.run-container.run.run-step-process.step-finished-with-error": true, "rep.depot-client.run-container.run.setup.download-step.fetch-starting": true, "rep.auction-delegate.auction-work.lrp-allocate-instances.requesting-container-allocation": true, "rep.event-consumer.operation-stream.executing-container-operation.task-processor.fetching-container-result": true, "rep.depot-client.run-container.run.action.run-step.running": true, } filteredSignificantEvents := analyzers.SignificantEvents{} filteredSignificantEvents.LogWithThreshold(0.2) for name, events := range significantEvents { if allow[name] { filteredSignificantEvents[name] = events } } filteredSignificantEvents.LogWithThreshold(0.2) limit := viz.NewHorizontalLine(256) limit.LineStyle = viz.LineStyle(viz.Red, 1) options := analyzers.SignificantEventsOptions{ LineOverlays: gardenStressTestContainerCountOverlays(entries), VerticalMarkers: gardenStressTestFailedContainerCreates(entries), OverlayPlots: []plot.Plotter{limit}, WidthStretch: 2, MaxY: 400, } analyzers.VisualizeSignificantEvents( filteredSignificantEvents, config.DataDir("garden-aufs-test", run+".png"), options, ) } }
func analyzeGardenDT() { data, err := ioutil.ReadFile(config.DataDir("garden-dt", "garden-dt.logs")) say.ExitIfError("couldn't read log file", err) entries := util.ChugLagerEntries(data) significantEvents := analyzers.ExtractSignificantEvents(entries) significantEvents.LogWithThreshold(0.2) delete(significantEvents, "garden-linux.container.info-starting") options := analyzers.SignificantEventsOptions{ MarkedEvents: map[string]plot.LineStyle{ "garden-linux.garden-server.create.creating": viz.LineStyle(viz.Blue, 1, viz.Dot), "garden-linux.garden-server.destroy.destroying": viz.LineStyle(viz.Red, 1, viz.Dot), }, } analyzers.VisualizeSignificantEvents( significantEvents, config.DataDir("garden-dt", "many-garden-dt.svg"), options, ) }
func analyzeGardenStressTests() { data, err := ioutil.ReadFile(config.DataDir("garden-stress-test", "all.unified")) say.ExitIfError("couldn't read log file", err) entries := util.ChugLagerEntries(data) significantEvents := analyzers.ExtractSignificantEvents(entries) allow := map[string]bool{ "garden-linux.garden-server.create.creating": true, "rep.depot-client.delete-container.destroy.started": true, } filteredSignificantEvents := analyzers.SignificantEvents{} filteredSignificantEvents.LogWithThreshold(0.2) for name, events := range significantEvents { if allow[name] { filteredSignificantEvents[name] = events } } filteredSignificantEvents.LogWithThreshold(0.2) limit := viz.NewHorizontalLine(256) limit.LineStyle = viz.LineStyle(viz.Red, 1) options := analyzers.SignificantEventsOptions{ LineOverlays: gardenStressTestContainerCountOverlays(entries), VerticalMarkers: gardenStressTestFailedContainerCreates(entries), OverlayPlots: []plot.Plotter{limit}, WidthStretch: 3, MaxY: 400, } analyzers.VisualizeSignificantEvents( filteredSignificantEvents, config.DataDir("garden-stress-test", "out.png"), options, ) }
func VisualizeSignificantEvents(events SignificantEvents, filename string, options SignificantEventsOptions) { firstTime := events.FirstTime() tr := func(t time.Time) float64 { return t.Sub(firstTime).Seconds() } minX := options.MinX maxX := 0.0 maxY := 0.0 minY := math.MaxFloat64 histograms := map[string]plot.Plotter{} scatters := map[string][]plot.Plotter{} verticalLines := []plot.Plotter{} colorCounter := 0 for _, name := range events.OrderedNames() { xys := plotter.XYs{} xErrs := plotter.XErrors{} for _, event := range events[name] { if event.V > 0 { xys = append(xys, struct{ X, Y float64 }{tr(event.T), event.V}) xErrs = append(xErrs, struct{ Low, High float64 }{-event.V / 2, event.V / 2}) if tr(event.T) > maxX { maxX = tr(event.T) } if event.V > maxY { maxY = event.V } if event.V < minY { minY = event.V } } } if len(xys) == 0 { say.Println(0, "No data for %s", name) continue } if options.MarkedEvents != nil { ls, ok := options.MarkedEvents[name] if ok { for _, event := range events[name] { l := viz.NewVerticalLine(tr(event.T)) l.LineStyle = ls verticalLines = append(verticalLines, l) } } } s, err := plotter.NewScatter(xys) say.ExitIfError("Couldn't create scatter plot", err) s.GlyphStyle = plot.GlyphStyle{ Color: viz.OrderedColor(colorCounter), Radius: 2, Shape: plot.CircleGlyph{}, } xErrsPlot, err := plotter.NewXErrorBars(struct { plotter.XYer plotter.XErrorer }{xys, xErrs}) say.ExitIfError("Couldn't create x errors plot", err) xErrsPlot.LineStyle = viz.LineStyle(viz.OrderedColor(colorCounter), 1) scatters[name] = []plot.Plotter{s, xErrsPlot} durations := events[name].Data() h := viz.NewHistogram(durations, 20, durations.Min(), durations.Max()) h.LineStyle = viz.LineStyle(viz.OrderedColor(colorCounter), 1) histograms[name] = h colorCounter++ } if options.MaxX != 0 { maxX = options.MaxX } maxY = math.Pow(10, math.Ceil(math.Log10(maxY))) minY = math.Pow(10, math.Floor(math.Log10(minY))) b := &viz.Board{} n := len(histograms) + 1 padding := 0.1 / float64(n-1) height := (1.0 - padding*float64(n-1)) / float64(n) histWidth := 0.3 scatterWidth := 0.7 y := 1 - height - padding - height allScatterPlot, _ := plot.New() allScatterPlot.Title.Text = "All Events" allScatterPlot.X.Label.Text = "Time (s)" allScatterPlot.Y.Label.Text = "Duration (s)" allScatterPlot.Y.Scale = plot.LogScale allScatterPlot.Y.Tick.Marker = plot.LogTicks for _, name := range events.OrderedNames() { histogram, ok := histograms[name] if !ok { continue } scatter := scatters[name] allScatterPlot.Add(scatter[0]) allScatterPlot.Add(scatter[1]) histogramPlot, _ := plot.New() histogramPlot.Title.Text = name histogramPlot.X.Label.Text = "Duration (s)" histogramPlot.Y.Label.Text = "N" histogramPlot.Add(histogram) scatterPlot, _ := plot.New() scatterPlot.Title.Text = name scatterPlot.X.Label.Text = "Time (s)" scatterPlot.Y.Label.Text = "Duration (s)" scatterPlot.Y.Scale = plot.LogScale scatterPlot.Y.Tick.Marker = plot.LogTicks scatterPlot.Add(scatter...) scatterPlot.Add(verticalLines...) scatterPlot.X.Min = minX scatterPlot.X.Max = maxX scatterPlot.Y.Min = 1e-5 scatterPlot.Y.Max = maxY b.AddSubPlot(histogramPlot, viz.Rect{0, y, histWidth, height}) b.AddSubPlot(scatterPlot, viz.Rect{histWidth, y, scatterWidth, height}) y -= height + padding } allScatterPlot.Add(verticalLines...) allScatterPlot.X.Min = minX allScatterPlot.X.Max = maxX allScatterPlot.Y.Min = 1e-5 allScatterPlot.Y.Max = maxY fmt.Println("all", minX, maxX) b.AddSubPlot(allScatterPlot, viz.Rect{histWidth, 1 - height, scatterWidth, height}) b.Save(16.0, 5*float64(n), filename) }
func VisualizeSignificantEvents(events SignificantEvents, filename string, options SignificantEventsOptions) { firstTime := events.FirstTime() tr := func(t time.Time) float64 { return t.Sub(firstTime).Seconds() } minX := 0.0 if options.MinX != 0 { minX = options.MinX } if !options.MinT.IsZero() { minX = tr(options.MinT) } maxX := 0.0 maxY := 0.0 minY := math.MaxFloat64 scatters := map[string][]plot.Plotter{} verticalLines := []plot.Plotter{} lineOverlays := []plot.Plotter{} colorCounter := 0 for _, name := range events.OrderedNames() { xys := plotter.XYs{} xErrs := plotter.XErrors{} for _, event := range events[name] { if event.V > 0 { xys = append(xys, struct{ X, Y float64 }{tr(event.T), event.V}) xErrs = append(xErrs, struct{ Low, High float64 }{-event.V / 2, event.V / 2}) if tr(event.T) > maxX { maxX = tr(event.T) } if event.V > maxY { maxY = event.V } if event.V < minY { minY = event.V } } } if len(xys) == 0 { say.Println(0, "No data for %s", name) continue } if options.MarkedEvents != nil { ls, ok := options.MarkedEvents[name] if ok { for _, event := range events[name] { l := viz.NewVerticalLine(tr(event.T)) l.LineStyle = ls verticalLines = append(verticalLines, l) } } } s, err := plotter.NewScatter(xys) say.ExitIfError("Couldn't create scatter plot", err) s.GlyphStyle = plot.GlyphStyle{ Color: viz.OrderedColor(colorCounter), Radius: 2, Shape: plot.CircleGlyph{}, } xErrsPlot, err := plotter.NewXErrorBars(struct { plotter.XYer plotter.XErrorer }{xys, xErrs}) say.ExitIfError("Couldn't create x errors plot", err) xErrsPlot.LineStyle = viz.LineStyle(viz.OrderedColor(colorCounter), 1) scatters[name] = []plot.Plotter{s, xErrsPlot} colorCounter++ } for _, marker := range options.VerticalMarkers { l := viz.NewVerticalLine(tr(marker.T)) l.LineStyle = marker.LineStyle verticalLines = append(verticalLines, l) } for _, lineOverlay := range options.LineOverlays { xys := plotter.XYs{} for _, event := range lineOverlay.Events { if event.V > 0 { xys = append(xys, struct{ X, Y float64 }{tr(event.T), event.V}) } } l, s, err := plotter.NewLinePoints(xys) say.ExitIfError("Couldn't create scatter plot", err) l.LineStyle = lineOverlay.LineStyle s.GlyphStyle = plot.GlyphStyle{ Color: lineOverlay.LineStyle.Color, Radius: lineOverlay.LineStyle.Width, Shape: plot.CrossGlyph{}, } lineOverlays = append(lineOverlays, l, s) } if options.MaxX != 0 { maxX = options.MaxX } if !options.MaxT.IsZero() { maxX = tr(options.MaxT) } maxY = math.Pow(10, math.Ceil(math.Log10(maxY))) if options.MaxY != 0 { maxY = options.MaxY } minY = math.Pow(10, math.Floor(math.Log10(minY))) n := len(scatters) + 1 b := viz.NewUniformBoard(1, n, 0.01) allScatterPlot, _ := plot.New() allScatterPlot.Title.Text = "All Events" allScatterPlot.X.Label.Text = "Time (s)" allScatterPlot.Y.Label.Text = "Duration (s)" allScatterPlot.Y.Scale = plot.LogScale allScatterPlot.Y.Tick.Marker = plot.LogTicks for i, name := range events.OrderedNames() { scatter, ok := scatters[name] if !ok { continue } allScatterPlot.Add(scatter[0]) allScatterPlot.Add(scatter[1]) scatterPlot, _ := plot.New() scatterPlot.Title.Text = name scatterPlot.X.Label.Text = "Time (s)" scatterPlot.Y.Label.Text = "Duration (s)" scatterPlot.Y.Scale = plot.LogScale scatterPlot.Y.Tick.Marker = plot.LogTicks scatterPlot.Add(scatter...) scatterPlot.Add(verticalLines...) scatterPlot.Add(lineOverlays...) scatterPlot.Add(options.OverlayPlots...) scatterPlot.X.Min = minX scatterPlot.X.Max = maxX scatterPlot.Y.Min = 1e-5 scatterPlot.Y.Max = maxY b.AddSubPlotAt(scatterPlot, 0, n-2-i) } allScatterPlot.Add(verticalLines...) allScatterPlot.Add(lineOverlays...) allScatterPlot.Add(options.OverlayPlots...) allScatterPlot.X.Min = minX allScatterPlot.X.Max = maxX allScatterPlot.Y.Min = 1e-5 allScatterPlot.Y.Max = maxY fmt.Println("all", minX, maxX) b.AddSubPlotAt(allScatterPlot, 0, n-1) width := 12.0 if options.WidthStretch > 0 { width = width * options.WidthStretch } b.Save(width, 5*float64(n), filename) }
func analyzeAuctioneerFetchStateDuration() { data, err := ioutil.ReadFile(config.DataDir("auctioneer-fetch-state-duration", "auctioneer-fetch-state-duration.logs")) say.ExitIfError("couldn't read log file", err) entries := util.ChugLagerEntries(data) fetchStateDurationEvents := ExtractEventsFromLagerData(entries, DurationExtractor("duration")) allDurations := fetchStateDurationEvents.Data() highDurations := allDurations.Filter(NumFilter(">", 0.2)) lowDurations := allDurations.Filter(NumFilter("<=", 0.2)) earlyAllDurations := fetchStateDurationEvents.FilterTimes(NumFilter("<", 1445274027070991039)).Data() earlyHighDurations := earlyAllDurations.Filter(NumFilter(">", 0.2)) earlyLowDurations := earlyAllDurations.Filter(NumFilter("<=", 0.2)) lateAllDurations := fetchStateDurationEvents.FilterTimes(NumFilter(">=", 1445274027070991039)).Data() lateHighDurations := lateAllDurations.Filter(NumFilter(">", 0.2)) lateLowDurations := lateAllDurations.Filter(NumFilter("<=", 0.2)) board := viz.NewUniformBoard(3, 1, 0) earlyScale := float64(len(allDurations)) / float64(len(earlyAllDurations)) lateScale := float64(len(allDurations)) / float64(len(lateAllDurations)) say.Println(0, "All Fetches: %s", allDurations.Stats()) say.Println(1, "> 0.2s: %s", highDurations.Stats()) say.Println(1, "<= 0.2s: %s", lowDurations.Stats()) say.Println(0, "Early Fetches: %s", earlyAllDurations.Stats()) say.Println(1, "> 0.2s: %s", earlyHighDurations.Stats()) say.Println(1, "<= 0.2s: %s", earlyLowDurations.Stats()) say.Println(0, "Late Fetches: %s", lateAllDurations.Stats()) say.Println(1, "> 0.2s: %s", lateHighDurations.Stats()) say.Println(1, "<= 0.2s: %s", lateLowDurations.Stats()) p, _ := plot.New() p.Title.Text = "All Auctioneer Fetch State Durations" p.Add(viz.NewHistogram(allDurations, 20, allDurations.Min(), allDurations.Max())) h := viz.NewScaledHistogram(earlyAllDurations, 20, allDurations.Min(), allDurations.Max(), earlyScale) h.LineStyle = viz.LineStyle(viz.Blue, 1) p.Add(h) h = viz.NewScaledHistogram(lateAllDurations, 20, allDurations.Min(), allDurations.Max(), lateScale) h.LineStyle = viz.LineStyle(viz.Red, 1) p.Add(h) board.AddNextSubPlot(p) p, _ = plot.New() p.Title.Text = "Auctioneer Fetch State Durations < 0.2s" p.Add(viz.NewHistogram(lowDurations, 100, lowDurations.Min(), lowDurations.Max())) h = viz.NewScaledHistogram(earlyLowDurations, 100, lowDurations.Min(), lowDurations.Max(), earlyScale) h.LineStyle = viz.LineStyle(viz.Blue, 1) p.Add(h) h = viz.NewScaledHistogram(lateLowDurations, 100, lowDurations.Min(), lowDurations.Max(), lateScale) h.LineStyle = viz.LineStyle(viz.Red, 1) p.Add(h) board.AddNextSubPlot(p) p, _ = plot.New() p.Title.Text = "Auctioneer Fetch State Durations > 0.2s" p.Add(viz.NewHistogram(highDurations, 40, highDurations.Min(), highDurations.Max())) h = viz.NewScaledHistogram(earlyHighDurations, 40, highDurations.Min(), highDurations.Max(), earlyScale) h.LineStyle = viz.LineStyle(viz.Blue, 1) p.Add(h) h = viz.NewScaledHistogram(lateHighDurations, 40, highDurations.Min(), highDurations.Max(), lateScale) h.LineStyle = viz.LineStyle(viz.Red, 1) p.Add(h) board.AddNextSubPlot(p) board.Save(12, 4, config.DataDir("auctioneer-fetch-state-duration", "auctioneer-fetch-state-duration.svg")) }