vm: faster output oops grepping

Use manual parsing instead of a regexp.
Regexp takes ~220ms for typical output size. New code takes ~2ms.
Brings manager CPU consumption from ~250% down to ~25%.

syz-manager/manager.go

@@ -249,7 +249,7 @@ func (mgr *Manager) runInstance(vmCfg *vm.Config, first bool) bool {
 			}
 		case out := <-outputC:
 			output = append(output, out...)
-			if loc := vm.CrashRe.FindAllIndex(output[matchPos:], -1); len(loc) != 0 {
+			if _, _, _, found := vm.FindCrash(output[matchPos:]); found {
 				// Give it some time to finish writing the error message.
 				timer := time.NewTimer(10 * time.Second).C
 			loop:
@@ -261,20 +261,16 @@ func (mgr *Manager) runInstance(vmCfg *vm.Config, first bool) bool {
 						break loop
 					}
 				}
-				loc = vm.CrashRe.FindAllIndex(output[matchPos:], -1)
-				for i := range loc {
-					loc[i][0] += matchPos
-					loc[i][1] += matchPos
-				}
-				start := loc[0][0] - beforeContext
+				desc, start, end, _ := vm.FindCrash(output[matchPos:])
+				start = start + matchPos - beforeContext
 				if start < 0 {
 					start = 0
 				}
-				end := loc[len(loc)-1][1] + afterContext
+				end = end + matchPos + afterContext
 				if end > len(output) {
 					end = len(output)
 				}
-				mgr.saveCrasher(vmCfg.Name, string(output[loc[0][0]:loc[0][1]]), output[start:end])
+				mgr.saveCrasher(vmCfg.Name, desc, output[start:end])
 			}
 			if len(output) > 2*beforeContext {
 				copy(output, output[len(output)-beforeContext:])

tools/syz-repro/repro.go

@@ -57,11 +57,11 @@ func main() {
 	entries := prog.ParseLog(data)
 	log.Printf("parsed %v programs", len(entries))
 
-	crashLoc := vm.CrashRe.FindIndex(data)
-	if crashLoc == nil {
+	crashDesc, crashStart, _, found := vm.FindCrash(data)
+	if !found {
 		log.Fatalf("can't find crash message in the log")
 	}
-	log.Printf("target crash: '%s'", data[crashLoc[0]:crashLoc[1]])
+	log.Printf("target crash: '%s'", crashDesc)
 
 	instances = make(chan VM, cfg.Count)
 	bootRequests = make(chan bool, cfg.Count)
@@ -90,7 +90,7 @@ func main() {
 		}()
 	}
 
-	repro(cfg, entries, crashLoc)
+	repro(cfg, entries, crashStart)
 
 	for {
 		select {
@@ -102,10 +102,10 @@ func main() {
 	}
 }
 
-func repro(cfg *config.Config, entries []*prog.LogEntry, crashLoc []int) {
+func repro(cfg *config.Config, entries []*prog.LogEntry, crashStart int) {
 	// Cut programs that were executed after crash.
 	for i, ent := range entries {
-		if ent.Start > crashLoc[0] {
+		if ent.Start > crashStart {
 			entries = entries[:i]
 			break
 		}
@@ -244,8 +244,8 @@ func testImpl(inst vm.Instance, command string, timeout time.Duration) (res bool
 		select {
 		case out := <-outc:
 			output = append(output, out...)
-			if loc := vm.CrashRe.FindIndex(output); loc != nil {
-				log.Printf("program crashed with '%s'", output[loc[0]:loc[1]])
+			if desc, _, _, found := vm.FindCrash(output); found {
+				log.Printf("program crashed with '%s'", desc)
 				return true
 			}
 		case err := <-errc:

vm/vm.go

@@ -4,9 +4,9 @@
 package vm
 
 import (
+	"bytes"
 	"errors"
 	"fmt"
-	"regexp"
 	"time"
 )
 
@@ -60,9 +60,50 @@ func Create(typ string, cfg *Config) (Instance, error) {
 	return ctor(cfg)
 }
 
+// FindCrash searches kernel console output for oops messages.
+// Desc contains a more-or-less representative description of the first oops,
+// start and end denote region of output with oops message(s).
+func FindCrash(output []byte) (desc string, start int, end int, found bool) {
+	for pos := 0; pos < len(output); {
+		next := bytes.IndexByte(output[pos:], '\n')
+		if next != -1 {
+			next += pos
+		} else {
+			next = len(output)
+		}
+		for _, oops := range oopses {
+			match := bytes.Index(output[pos:next], oops)
+			if match == -1 {
+				continue
+			}
+			if !found {
+				found = true
+				start = pos
+				desc = string(output[pos+match : next])
+				if desc[len(desc)-1] == '\r' {
+					desc = desc[:len(desc)-1]
+				}
+			}
+			end = next
+		}
+		pos = next + 1
+	}
+	return
+}
+
 var (
-	CrashRe = regexp.MustCompile("Kernel panic[^\r\n]*|BUG:[^\r\n]*|kernel BUG[^\r\n]*|WARNING:[^\r\n]*|" +
-		"INFO:[^\r\n]*|unable to handle|Unable to handle kernel[^\r\n]*|general protection fault|UBSAN:[^\r\n]*|" +
-		"unreferenced object[^\r\n]*")
+	oopses = [][]byte{
+		[]byte("Kernel panic"),
+		[]byte("BUG:"),
+		[]byte("kernel BUG"),
+		[]byte("WARNING:"),
+		[]byte("INFO:"),
+		[]byte("unable to handle"),
+		[]byte("Unable to handle kernel"),
+		[]byte("general protection fault"),
+		[]byte("UBSAN:"),
+		[]byte("unreferenced object"),
+	}
+
 	TimeoutErr = errors.New("timeout")
 )

vm/vm_test.go

@@ -8,7 +8,7 @@ import (
 	"testing"
 )
 
-func TestCrashRe(t *testing.T) {
+func TestFindCrash(t *testing.T) {
 	tests := map[string]string{
 		`
 [   50.583499] something 
@@ -23,7 +23,7 @@ func TestCrashRe(t *testing.T) {
 		`
 [   50.583499] general protection fault: 0000 [#1] SMP KASAN
 [   50.583499] Modules linked in: 
-`: "general protection fault",
+`: "general protection fault: 0000 [#1] SMP KASAN",
 		`
 [   50.583499] BUG: unable to handle kernel NULL pointer dereference at 000000000000003a
 [   50.583499] Modules linked in: 
@@ -82,19 +82,16 @@ locks_free_lock_context+0x118/0x180()
 		tests[strings.Replace(log, "\n", "\r\n", -1)] = crash
 	}
 	for log, crash := range tests {
-		loc := CrashRe.FindStringIndex(log)
-		if loc == nil && crash != "" {
+		desc, _, _, found := FindCrash([]byte(log))
+		//t.Logf("%v\nexpect '%v', found '%v'\n", log, crash, desc)
+		if !found && crash != "" {
 			t.Fatalf("did not find crash message '%v' in:\n%v", crash, log)
 		}
-		if loc != nil && crash == "" {
-			t.Fatalf("found bogus crash message '%v' in:\n%v", log[loc[0]:loc[1]], log)
+		if found && crash == "" {
+			t.Fatalf("found bogus crash message '%v' in:\n%v", desc, log)
 		}
-		if loc == nil {
-			continue
-		}
-		crash1 := log[loc[0]:loc[1]]
-		if crash1 != crash {
-			t.Fatalf("extracted bad crash message:\n%v\nwant:\n%v", crash1, crash)
+		if desc != crash {
+			t.Fatalf("extracted bad crash message:\n%v\nwant:\n%v", desc, crash)
 		}
 	}
 }