X hook in tracing for gc tests; no tests itself yet

go/neo/client/cache.go

@@ -20,6 +20,9 @@
 package client
 // cache management
 
+// XXX gotrace ... -> gotrace gen ...
+//go:generate sh -c "go run ../../xcommon/tracing/cmd/gotrace/{gotrace,util}.go ."
+
 import (
 	"fmt"
 	"sort"
@@ -112,7 +115,7 @@ type revCacheEntry struct {
 
 // NewCache creates new cache backed up by loader.
 //
-// The cache will use not more than ~ sizeMax bytes of RAM for data.
+// The cache will use not more than ~ sizeMax bytes of RAM for cached data.
 func NewCache(loader storLoader, sizeMax int) *Cache {
 	c := &Cache{
 		loader:   loader,
@@ -125,6 +128,22 @@ func NewCache(loader storLoader, sizeMax int) *Cache {
 	return c
 }
 
+// SetSizeMax adjusts how much RAM cache can use for cached data.
+func (c *Cache) SetSizeMax(sizeMax int) {
+	gcrun := false
+
+	c.gcMu.Lock()
+	c.sizeMax = sizeMax
+	if c.size > c.sizeMax {
+		gcrun = true
+	}
+	c.gcMu.Unlock()
+
+	if gcrun {
+		c.gcsignal()
+	}
+}
+
 // Load loads data from database via cache.
 //
 // If data is already in cache cached content is returned.
@@ -345,7 +364,7 @@ func (c *Cache) loadRCE(rce *revCacheEntry, oid zodb.Oid) {
 	oce.Unlock()
 
 	// update lru & cache size
-	rungc := false
+	gcrun := false
 	c.gcMu.Lock()
 	//xv1 := map[string]interface{}{"lru": &c.lru, "rce": &rce.inLRU}
 	//fmt.Printf("aaa:\n%s\n", pretty.Sprint(xv1))
@@ -360,11 +379,11 @@ func (c *Cache) loadRCE(rce *revCacheEntry, oid zodb.Oid) {
 
 	c.size += δsize
 	if c.size > c.sizeMax {
-		rungc = true
+		gcrun = true
 	}
 	c.gcMu.Unlock()
 
-	if rungc {
+	if gcrun {
 		c.gcsignal()
 	}
 }
@@ -458,8 +477,14 @@ func (c *Cache) gcmain() {
 	}
 }
 
+//trace:event traceCacheGCStart(c *Cache)
+//trace:event traceCacheGCFinish(c *Cache)
+
 // gc performs garbage-collection
 func (c *Cache) gc() {
+	traceCacheGCStart(c)
+	defer traceCacheGCFinish(c)
+
 	fmt.Printf("\n> gc\n")
 	defer fmt.Printf("< gc\n")
 	for {

go/neo/client/cache_test.go

@@ -29,6 +29,9 @@ import (
 
 	"github.com/kylelemons/godebug/pretty"
 	"lab.nexedi.com/kirr/neo/go/zodb"
+
+	"lab.nexedi.com/kirr/neo/go/xcommon/tracing"
+	"lab.nexedi.com/kirr/neo/go/xcommon/xtesting"
 )
 
 // tStorage implements read-only storage for cache testing
@@ -94,24 +97,44 @@ func xideq(oid zodb.Oid, tid zodb.Tid) zodb.Xid {
 	return zodb.Xid{Oid: oid, XTid: zodb.XTid{Tid: tid, TidBefore: false}}
 }
 
+// tracer which collects tracing events from all needed-for-tests sources
+type tTracer struct {
+	*xtesting.SyncTracer
+}
+
+type evCacheGCStart struct {
+	c *Cache
+}
+func (t *tTracer) traceCacheGCStart(c *Cache)	{ t.Trace1(&evCacheGCStart{c}) }
+
+type evCacheGCFinish struct {
+	c *Cache
+}
+func (t *tTracer) traceCacheGCFinish(c *Cache)	{ t.Trace1(&evCacheGCFinish{c}) }
+
 func TestCache(t *testing.T) {
 	// XXX hack; place=ok?
 	pretty.CompareConfig.PrintStringers = true
 	debug := pretty.DefaultConfig
 	debug.IncludeUnexported = true
 
-	// XXX <100 <90 <80
-	//	q<110	-> a) 110 <= cache.before   b) otherwise
-	//	q<85	-> a) inside 90.serial..90  b) outside
-	//
-	// XXX cases when .serial=0 (not yet determined - 1st loadBefore is in progress)
-	// XXX for every serial check before = (s-1, s, s+1)
+	__ := Checker{t}
+	ok1 := func(v bool) { t.Helper(); __.ok1(v) }
+	//eq  := func(a, b interface{}) { t.Helper(); __.assertEq(a, b) }
+
+	// attach to Cache GC tracepoints
+	tracer := &tTracer{xtesting.NewSyncTracer()}
+	pg := &tracing.ProbeGroup{}
+	defer pg.Done()
+
+	tracing.Lock()
+	traceCacheGCStart_Attach(pg, tracer.traceCacheGCStart)
+	traceCacheGCFinish_Attach(pg, tracer.traceCacheGCFinish)
+	tracing.Unlock()
 
-	// merge: rcePrev + (rce + rceNext) ?
+	// trace-checker for the events
+	tc := xtesting.NewTraceChecker(t, tracer.SyncTracer)
 
-	tc := Checker{t}
-	ok1 := func(v bool) { t.Helper(); tc.ok1(v) }
-	//eq  := func(a, b interface{}) { t.Helper(); tc.assertEq(a, b) }
 
 	hello := []byte("hello")
 	world := []byte("world!!")
@@ -458,7 +481,13 @@ func TestCache(t *testing.T) {
 	checkMRU(17, rce1_b16, rce1_b7, rce1_b9, rce1_b22, rce1_b20, rce1_b10, rce1_b8, rce1_b4)
 
 
-	// XXX verify LRU eviction
+	// ---- verify LRU eviction ----
+
+	gcstart  := &evCacheGCStart{c}
+	//gcfinish := &evCacheGCFinish{c}
+
+	tc.Expect(gcstart)
+
 	// XXX verify db inconsistency checks
 	// XXX verify loading with before > cache.before
 }

go/neo/client/ztrace.go

+// Code generated by lab.nexedi.com/kirr/go123/tracing/cmd/gotrace; DO NOT EDIT.
+
+package client
+// code generated for tracepoints
+
+import (
+	"lab.nexedi.com/kirr/neo/go/xcommon/tracing"
+	"unsafe"
+)
+
+// traceevent: traceCacheGCFinish(c *Cache)
+
+type _t_traceCacheGCFinish struct {
+	tracing.Probe
+	probefunc     func(c *Cache)
+}
+
+var _traceCacheGCFinish *_t_traceCacheGCFinish
+
+func traceCacheGCFinish(c *Cache) {
+	if _traceCacheGCFinish != nil {
+		_traceCacheGCFinish_run(c)
+	}
+}
+
+func _traceCacheGCFinish_run(c *Cache) {
+	for p := _traceCacheGCFinish; p != nil; p = (*_t_traceCacheGCFinish)(unsafe.Pointer(p.Next())) {
+		p.probefunc(c)
+	}
+}
+
+func traceCacheGCFinish_Attach(pg *tracing.ProbeGroup, probe func(c *Cache)) *tracing.Probe {
+	p := _t_traceCacheGCFinish{probefunc: probe}
+	tracing.AttachProbe(pg, (**tracing.Probe)(unsafe.Pointer(&_traceCacheGCFinish)), &p.Probe)
+	return &p.Probe
+}
+
+// traceevent: traceCacheGCStart(c *Cache)
+
+type _t_traceCacheGCStart struct {
+	tracing.Probe
+	probefunc     func(c *Cache)
+}
+
+var _traceCacheGCStart *_t_traceCacheGCStart
+
+func traceCacheGCStart(c *Cache) {
+	if _traceCacheGCStart != nil {
+		_traceCacheGCStart_run(c)
+	}
+}
+
+func _traceCacheGCStart_run(c *Cache) {
+	for p := _traceCacheGCStart; p != nil; p = (*_t_traceCacheGCStart)(unsafe.Pointer(p.Next())) {
+		p.probefunc(c)
+	}
+}
+
+func traceCacheGCStart_Attach(pg *tracing.ProbeGroup, probe func(c *Cache)) *tracing.Probe {
+	p := _t_traceCacheGCStart{probefunc: probe}
+	tracing.AttachProbe(pg, (**tracing.Probe)(unsafe.Pointer(&_traceCacheGCStart)), &p.Probe)
+	return &p.Probe
+}
+
+// trace export signature
+func _trace_exporthash_624de1c8d179b91f695f79fec7f7cdb7386501f4() {}

go/xcommon/tracing/tracing.go

@@ -115,6 +115,7 @@ though there it records only predefined set of events related to Go runtime.
 TODO tracing should provide infrastructure to write events out in format
 understood by chromium trace-viewer: https://github.com/catapult-project/catapult/tree/master/tracing
 
+NOTE there is also talk/work to implement user events for runtime/trace: https://golang.org/issues/16619.
 
 Profiling
 

go/xcommon/xtesting/xtesting.go

@@ -43,7 +43,8 @@ type SyncTracer struct {
 	tracech chan *SyncTraceMsg
 }
 
-// SyncTraceMsg represents message with 1 synchronous tracing communication
+// SyncTraceMsg represents message with 1 synchronous tracing communication.
+//
 // the goroutine which produced the message will wait for send on Ack before continue.
 type SyncTraceMsg struct {
 	Event interface {}
@@ -63,7 +64,8 @@ func (st *SyncTracer) Trace1(event interface{}) {
 	<-ack
 }
 
-// Get1 receives message with 1 tracing event from a producer
+// Get1 receives message with 1 tracing event from a producer.
+//
 // The consumer, after dealing with the message, must send back an ack.
 func (st *SyncTracer) Get1() *SyncTraceMsg {
 	msg := <-st.tracech