featurebase/generation_debug.go

// Copyright 2019 Pilosa Corp.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//     http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

// +build generationdebug

package pilosa

import (
	"fmt"
	"math/rand"
	"runtime"
	"runtime/debug"
	"sort"
	"sync"
	"time"
)

const generationDebug = true

type lifespan struct {
	from, to, finalized time.Time
	stack               []byte
}

var knownGenerations map[string]lifespan
var knownGenerationLock sync.Mutex

var timeZero time.Time

var generationDebugVerbose bool

// History reports the finalized/dead/created status of a span which we think
// is in some way in error. It's shared between a couple of places.
func (span *lifespan) History() string {
	dead := "not dead"
	finalized := "not finalized"
	if span.finalized != timeZero {
		finalized = fmt.Sprintf("finalized at %v", span.finalized)
	}
	if span.to != timeZero {
		dead = fmt.Sprintf("dead at %v", span.to)
	}
	return fmt.Sprintf("%s, %s, created at %v at %s", dead, finalized, span.from, span.stack)
}

func (span *lifespan) reportHistory(reason string, id string) string {
	return fmt.Sprintf("%s %s: %s", id, reason, span.History())
}

func registerGeneration(id string) string {
	knownGenerationLock.Lock()
	defer knownGenerationLock.Unlock()
	if knownGenerations == nil {
		knownGenerations = make(map[string]lifespan)
	}
	newSpan := lifespan{from: time.Now(), stack: debug.Stack()}
	origId := id

	// if you have more than 65k of the same file open, maybe you have bigger
	// problems than this.
	for span, exists := knownGenerations[id]; exists; span, exists = knownGenerations[id] {
		suffix := fmt.Sprintf("::%04x", rand.Int63n(65536))
		if generationDebugVerbose {
			history := span.History()
			fmt.Printf("new generation: adding suffix %s, previous %s\n",
				suffix, history)
		}
		id = origId + suffix
	}
	if generationDebugVerbose {
		fmt.Printf("new generation %s\n", id)
	}
	knownGenerations[id] = newSpan
	return id
}

func endGeneration(id string) {
	knownGenerationLock.Lock()
	defer knownGenerationLock.Unlock()
	span, exists := knownGenerations[id]
	if !exists {
		oops := fmt.Sprintf("ending generation %s: unknown", id)
		panic(oops)
	}
	if span.finalized != timeZero || span.to != timeZero {
		panic(span.reportHistory("ending generation", id))
	}
	span.to = time.Now()
	knownGenerations[id] = span
}

// cancelGeneration marks the generation as finalized. In principle it's
// only used in cases where we just started a generation but something
// went wrong. it's not fancier than this because of the weird cases
// where the same generation shows up again, such as when closing and
// reopening an index so we don't know about previous instances of the
// same files.
func cancelGeneration(id string) {
	knownGenerationLock.Lock()
	defer knownGenerationLock.Unlock()
	span, exists := knownGenerations[id]
	if exists {
		span.finalized = time.Now()
		span.to = span.finalized
		knownGenerations[id] = span
	}
}

func finalizeGeneration(id string) {
	knownGenerationLock.Lock()
	defer knownGenerationLock.Unlock()
	span, exists := knownGenerations[id]
	if !exists {
		oops := fmt.Sprintf("finalizing generation %s: unknown", id)
		panic(oops)
	}
	if span.finalized != timeZero {
		panic(span.reportHistory("finalizing", id))
	}
	span.finalized = time.Now()
	knownGenerations[id] = span
}

func reportGenerations() (stats string, surviving []string) {
	runtime.GC()
	knownGenerationLock.Lock()
	defer knownGenerationLock.Unlock()
	times := make([]int64, 0, len(knownGenerations))
	for id, span := range knownGenerations {
		if span.to == timeZero || span.finalized == timeZero {
			surviving = append(surviving, span.reportHistory("surviving", id))
		} else {
			times = append(times, int64(span.finalized.Sub(span.to)))
		}
	}
	stats = "no recorded finalized spans"
	if len(times) > 0 {
		sort.Slice(times, func(i, j int) bool { return times[i] < times[j] })
		var total int64
		for _, d := range times {
			total += d
		}
		var mean, median, p90, p99, worst int64
		mean = total / int64(len(times))
		median = times[len(times)/2]
		p90 = times[(len(times)*9)/10]
		p99 = times[(len(times)*99)/100]
		worst = times[len(times)-1]
		stats = fmt.Sprintf("%d finalized spans. lag: mean %v, median %v, p90 %v, p99 %v, worst %v",
			len(times), time.Duration(mean), time.Duration(median), time.Duration(p90), time.Duration(p99), time.Duration(worst))
	}
	return stats, surviving
}