goparsify/debugon.go

// +build debug

package goparsify

import (
	"bytes"
	"fmt"
	"io"
	"sort"
	"strconv"
	"strings"
	"time"

	"github.com/oec/goparsify/debug"
)

var log io.Writer = nil
var parsers []*debugParser
var pendingOpenLog = ""
var activeParsers []*debugParser
var longestLocation = 0

type debugParser struct {
	Match      string
	Var        string
	Location   string
	Next       Parser
	Cumulative time.Duration
	Self       time.Duration
	SelfStart  time.Time
	Calls      int
	Errors     int
}

func (dp *debugParser) Name() string {
	if len(activeParsers) > 1 && activeParsers[len(activeParsers)-2].Var == dp.Var {
		return dp.Match
	}
	return dp.Var
}

func (dp *debugParser) logf(ps *State, result *Result, format string, args ...interface{}) string {
	buf := &bytes.Buffer{}
	buf.WriteString(fmt.Sprintf("%"+strconv.Itoa(longestLocation)+"s | ", dp.Location))
	buf.WriteString(fmt.Sprintf("%-15s", ps.Preview(15)))
	buf.WriteString(" | ")
	buf.WriteString(strings.Repeat("  ", len(activeParsers)-1))
	buf.WriteString(fmt.Sprint(append([]interface{}{format}, args...)...))
	if ps.Errored() {
		buf.WriteString(fmt.Sprintf(" did not find %s", ps.Error.expected))
	} else if result != nil {
		resultStr := strconv.Quote(result.String())
		if len(resultStr) > 20 {
			resultStr = resultStr[0:20]
		}
		buf.WriteString(fmt.Sprintf(" found %s", resultStr))
	}
	buf.WriteRune('\n')
	return buf.String()
}

func (dp *debugParser) logStart(ps *State) {
	if log != nil {
		if pendingOpenLog != "" {
			fmt.Fprint(log, pendingOpenLog)
			pendingOpenLog = ""
		}
		pendingOpenLog = dp.logf(ps, nil, dp.Name()+" {")
	}
}

func (dp *debugParser) logEnd(ps *State, result *Result) {
	if log != nil {
		if pendingOpenLog != "" {
			fmt.Fprintf(log, dp.logf(ps, result, dp.Name()))
			pendingOpenLog = ""
		} else {
			fmt.Fprintf(log, dp.logf(ps, result, "}"))
		}
	}
}

func (dp *debugParser) Parse(ps *State, node *Result) {
	activeParsers = append(activeParsers, dp)
	start := time.Now()
	dp.SelfStart = start

	dp.logStart(ps)
	dp.Next(ps, node)
	dp.logEnd(ps, node)

	dp.Cumulative += time.Since(start)
	dp.Self += time.Since(dp.SelfStart)
	dp.Calls++
	if ps.Errored() {
		dp.Errors++
	}

	activeParsers = activeParsers[0 : len(activeParsers)-1]
}

// NewParser should be called around the creation of every Parser.
// It does nothing normally and should incur no runtime overhead, but when building with -tags debug
// it will instrument every parser to collect valuable timing and debug information.
func NewParser(name string, p Parser) Parser {
	description, location := debug.GetDefinition()

	dp := &debugParser{
		Match:    name,
		Var:      description,
		Location: location,
	}

	dp.Next = func(ps *State, ret *Result) {
		dp.Self += time.Since(dp.SelfStart)

		p(ps, ret)

		dp.SelfStart = time.Now()
	}

	if len(dp.Location) > longestLocation {
		longestLocation = len(dp.Location)
	}

	parsers = append(parsers, dp)
	return dp.Parse
}

// EnableLogging will write logs to the given writer as the next parse happens
func EnableLogging(w io.Writer) {
	log = w
}

// DisableLogging will stop writing logs
func DisableLogging() {
	log = nil
}

// DumpDebugStats will print out the curring timings for each parser if built with -tags debug
func DumpDebugStats() {
	sort.Slice(parsers, func(i, j int) bool {
		return parsers[i].Cumulative >= parsers[j].Cumulative
	})

	fmt.Println()
	fmt.Println("|             var name |              matches |      total time |       self time |      calls |     errors | location  ")
	fmt.Println("| -------------------- | -------------------- | --------------- | --------------- | ---------- | ---------- | ----------")
	for _, parser := range parsers {
		fmt.Printf("| %20s | %20s | %15s | %15s | %10d | %10d | %s\n", parser.Var, parser.Match, parser.Cumulative.String(), parser.Self.String(), parser.Calls, parser.Errors, parser.Location)
	}
}