Chore(raft): Add debug logs to print all transactions (#8890)

Add debug logs to print all transactions. This will reside under
BUILD_TAGS=debug.


Live loader time on main: 17 min 28 sec
Live loader time with change: 16mins 21 sec
Live loader time with change, with debug on: 18 min 9 sec

Debug logs looks like:
```
ADDING MUTATION at TS: 2533, key: UID: 3119251, Attr: 0-starring, Data key, value: entity:3119251 attr:"0-starring" value_type:UID value_id:1232342  
Doing rollup for key: {4 0-director.film 1211879 false 0  0 0} at timestamp: 1580
COMMITING: 1691 1702
```
Fixes: DGRAPHCORE-17

posting/list.go

@@ -524,6 +524,8 @@ func (l *List) addMutationInternal(ctx context.Context, txn *Txn, t *pb.Directed
 			hex.EncodeToString(l.key), mpost)
 	}
 
+	x.PrintMutationEdge(t, pk, txn.StartTs)
+
 	// We ensure that commit marks are applied to posting lists in the right
 	// order. We can do so by proposing them in the same order as received by the Oracle delta
 	// stream from Zero, instead of in goroutines.
@@ -897,6 +899,7 @@ func (l *List) Rollup(alloc *z.Allocator, readTs uint64) ([]*bpb.KV, error) {
 		return bytes.Compare(kvs[i].Key, kvs[j].Key) <= 0
 	})
 
+	x.PrintRollup(out.plist, out.parts, l.key, kv.Version)
 	x.VerifyPostingSplits(kvs, out.plist, out.parts, l.key)
 	return kvs, nil
 }

worker/draft.go

@@ -812,6 +812,7 @@ func (n *node) processApplyCh() {
 
 // TODO(Anurag - 4 May 2020): Are we using pkey? Remove if unused.
 func (n *node) commitOrAbort(pkey uint64, delta *pb.OracleDelta) error {
+	x.PrintOracleDelta(delta)
 	// First let's commit all mutations to disk.
 	writer := posting.NewTxnWriter(pstore)
 	toDisk := func(start, commit uint64) {

x/debug.go

@@ -24,11 +24,28 @@ import (
 	"log"
 	"sort"
 
+	"github.com/golang/glog"
+
 	"github.com/dgraph-io/badger/v4"
 	bpb "github.com/dgraph-io/badger/v4/pb"
 	"github.com/dgraph-io/dgraph/protos/pb"
 )
 
+func PrintRollup(plist *pb.PostingList, parts map[uint64]*pb.PostingList, baseKey []byte, ts uint64) {
+	k, _ := Parse(baseKey)
+	glog.V(2).Infof("[TXNLOG] DOING ROLLUP for key: %+v at timestamp: %v", k, ts)
+}
+
+func PrintMutationEdge(plist *pb.DirectedEdge, key ParsedKey, startTs uint64) {
+	glog.V(2).Infof("[TXNLOG] ADDING MUTATION at TS: %v, key: %v, value: %v", startTs, key.String(), plist)
+}
+
+func PrintOracleDelta(delta *pb.OracleDelta) {
+	for _, status := range delta.Txns {
+		glog.V(2).Infof("[TXNLOG] COMMITING: startTs: %v, commitTs: %v", status.StartTs, status.CommitTs)
+	}
+}
+
 // VerifyPack checks that the Pack should not be nil if the postings exist.
 func VerifyPack(plist *pb.PostingList) {
 	if plist.Pack == nil && len(plist.Postings) > 0 {

x/keys.go

@@ -19,6 +19,7 @@ package x
 import (
 	"encoding/binary"
 	"encoding/hex"
+	"fmt"
 	"math"
 	"strconv"
 	"strings"
@@ -300,6 +301,16 @@ type ParsedKey struct {
 	bytePrefix  byte
 }
 
+func (p ParsedKey) String() string {
+	if p.IsIndex() {
+		return fmt.Sprintf("UID: %v, Attr: %v, IsIndex: true, Term: %v", p.Uid, p.Attr, p.Count)
+	} else if p.IsCountOrCountRev() {
+		return fmt.Sprintf("UID: %v, Attr: %v, IsCount/Ref: true, Count: %v", p.Uid, p.Attr, p.Count)
+	} else {
+		return fmt.Sprintf("UID: %v, Attr: %v, Data key", p.Uid, p.Attr)
+	}
+}
+
 // IsData returns whether the key is a data key.
 func (p ParsedKey) IsData() bool {
 	return (p.bytePrefix == DefaultPrefix || p.bytePrefix == ByteSplit) && p.ByteType == ByteData

x/nodebug.go

@@ -25,6 +25,18 @@ import (
 	"github.com/dgraph-io/dgraph/protos/pb"
 )
 
+// PrintRollup prints information about any rollup that happen
+func PrintRollup(plist *pb.PostingList, parts map[uint64]*pb.PostingList, baseKey []byte, ts uint64) {
+}
+
+// PrintMutationEdge prints all edges that are being inserted into badger
+func PrintMutationEdge(plist *pb.DirectedEdge, key ParsedKey, startTs uint64) {
+}
+
+// PrintOracleDelta prints all delta proposals that are commited
+func PrintOracleDelta(delta *pb.OracleDelta) {
+}
+
 // VerifyPack works in debug mode. Check out the comment in debug_on.go
 func VerifyPack(plist *pb.PostingList) {
 }