P2P Message Execution Tracing #517

d1vyank · 2018-09-14T08:23:41Z

Adds a reusable tracing adapter that is applied to both beacon-chain and validator.
--enable-tracing, trace-sample-fraction, and --tracing-endpoint CLI options added
Define trace spans for existing p2p messages for a breakdown on how processing time is spent.

towards #438

CLAassistant · 2018-09-14T08:23:47Z

All committers have signed the CLA.

shared/p2p/adapter/tracer/tracer.go

d1vyank · 2018-09-14T08:26:46Z

shared/p2p/adapter/tracer/tracer.go

+		return nil, errors.New("tracing service name cannot be empty")
+	}
+
+	// TODO: make sampling fraction configurable?


Thoughts on this? Currently hard-coded to sampling 25% of requests.

That'd be awesome. Feel free to open an issue and change it to TODO(#Issue number)

Done, made this configurable.

Please format as TODO(#issue number)

terencechain

Thanks for the PR. Can't wait to try it later!

shared/cmd/flags.go

terencechain · 2018-09-14T20:29:48Z

shared/cmd/flags.go

+		Name:  "disable-tracing",
+		Usage: "Disable request tracing",
+	}
+	// TracingEndpointFlag flag defines the http enpoint for serving traces to Jaeger


terencechain · 2018-09-14T20:30:26Z

shared/p2p/adapter/tracer/tracer.go

+
+var log = logrus.WithField("prefix", "tracer")
+
+// New creates and initializes a new tracing adapter


terencechain · 2018-09-14T20:31:26Z

shared/p2p/adapter/tracer/tracer.go

+		return nil, errors.New("tracing service name cannot be empty")
+	}
+
+	// TODO: make sampling fraction configurable?


That'd be awesome. Feel free to open an issue and change it to TODO(#Issue number)

shared/p2p/message.go

prestonvanloon

Looking good! I can't wait to try it

shared/cmd/flags.go

prestonvanloon · 2018-09-15T02:11:25Z

shared/p2p/adapter/tracer/tracer.go

+)
+
+const (
+	defaultSamplingFraction = 0.25


Should this be a flag?

prestonvanloon · 2018-09-15T02:14:31Z

shared/p2p/message.go

 	"reflect"

 	"github.com/golang/protobuf/proto"
 )

 // Message represents a message received from an external peer.
 type Message struct {
+	// Ctx message context


You can omit this. It doesn't add any additional information

shared/p2p/adapter/tracer/tracer.go

prestonvanloon · 2018-09-15T02:34:00Z

shared/p2p/service.go

@@ -119,7 +119,7 @@ func (s *Server) RegisterTopic(topic string, message proto.Message, adapters ...
 			}

 			var h Handler = func(ctx context.Context, pMsg Message) {
-				s.emit(feed, msg, msgType)
+				s.emit(pMsg.Ctx, feed, msg, msgType)
 			}

 			pMsg := Message{}


Let's assign a context here and remove the context parameter from the adapter functions, as you suggested.

prestonvanloon · 2018-09-15T02:34:24Z

shared/p2p/service.go

@@ -119,7 +119,7 @@ func (s *Server) RegisterTopic(topic string, message proto.Message, adapters ...
 			}

 			var h Handler = func(ctx context.Context, pMsg Message) {
-				s.emit(feed, msg, msgType)
+				s.emit(pMsg.Ctx, feed, msg, msgType)


Can you pass the whole message?

shared/p2p/service.go

d1vyank · 2018-09-17T08:21:45Z

Addressed feedback. Here's what the traces look like if you're curious:

In Jaeger:

In pprof:

prestonvanloon · 2018-09-18T01:23:12Z

shared/p2p/adapter/tracer/tracer.go

+		var messageSpan *trace.Span
+		msg.Ctx, messageSpan = trace.StartSpan(msg.Ctx, "handleP2pMessage")
+		next(msg)
+		messageSpan.End()


Will this work properly when the message is handled in a go routine? The typical lifecycle for a message is:

Receive message

Apply adapters

Emit message to feed subscribers that are running in other go routines

End routine for handling message <- I think your span will end here, no?

Message received via feed to subscriber 1

Message received via feed to subscriber 2

This span only traces the handling of a message in the p2p layer and will end after the emit step as you mentioned. However, since the message context is passed to subscribers 1 and 2, any spans created there will be children of this root and linked to the message trace.
I expect the subscribing routines to define these child spans. (See receiveBlockHash in beacon chain sync service for an example)

Ah, I see. That makes sense.

One last request, can you add an example of how to instrument code in your readme?
It would be helpful to point someone to a canonical example in documentation.

After that, I think this is good to go!

Updated doc

codecov · 2018-09-19T08:55:39Z

Codecov Report

Merging #517 into master will increase coverage by 0.43%.
The diff coverage is 79.25%.

@@            Coverage Diff             @@
##           master     #517      +/-   ##
==========================================
+ Coverage   76.18%   76.62%   +0.43%     
==========================================
  Files          41       42       +1     
  Lines        2818     2879      +61     
==========================================
+ Hits         2147     2206      +59     
- Misses        472      473       +1     
- Partials      199      200       +1

Impacted Files	Coverage Δ
shared/p2p/message.go	`100% <ø> (ø)`	⬆️
shared/p2p/service.go	`67.01% <100%> (+0.34%)`	⬆️
shared/p2p/adapter/tracer/tracer.go	`100% <100%> (ø)`
beacon-chain/node/node.go	`59.49% <66.66%> (ø)`	⬆️
validator/node/node.go	`45.37% <66.66%> (ø)`	⬆️
beacon-chain/sync/service.go	`75.59% <73.17%> (+7.62%)`	⬆️
beacon-chain/node/p2p_config.go	`71.42% <75%> (-3.58%)`	⬇️
validator/node/p2p_config.go	`71.42% <75%> (-3.58%)`	⬇️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 75d3258...24a52c3. Read the comment docs.

prestonvanloon · 2018-09-20T03:08:42Z

@d1vyank please resolve conflicts then we can merge.

Thanks!

* Request execution tracing initial commit * Resolve linter issues * Run gazelle * Make trace sampling configurable, clean up, update doc * Document trace span creation * Fix linter issue

Request execution tracing initial commit

7adfa20

d1vyank commented Sep 14, 2018

View reviewed changes

shared/p2p/adapter/tracer/tracer.go Outdated Show resolved Hide resolved

d1vyank commented Sep 14, 2018

View reviewed changes

d1vyank added 2 commits September 14, 2018 14:05

Resolve linter issues

950bd29

Run gazelle

fc2aac3

terencechain requested a review from prestonvanloon September 14, 2018 16:05

terencechain reviewed Sep 14, 2018

View reviewed changes

prestonvanloon reviewed Sep 15, 2018

View reviewed changes

rauljordan changed the title ~~P2P message execution tracing~~ P2P Message Execution Tracing Sep 17, 2018

d1vyank added 2 commits September 17, 2018 13:25

Make trace sampling configurable, clean up, update doc

2b9c835

Merge remote-tracking branch 'origin' into tracing

7fc2f89

prestonvanloon reviewed Sep 18, 2018

View reviewed changes

d1vyank added 2 commits September 18, 2018 12:10

Merge remote-tracking branch 'origin/master' into tracing

dcd9e12

Document trace span creation

930cc82

prestonvanloon approved these changes Sep 18, 2018

View reviewed changes

d1vyank added 2 commits September 18, 2018 19:43

Merge remote-tracking branch 'origin' into tracing

a9e5637

Merge remote-tracking branch 'origin' into tracing

4b673ad

d1vyank added 3 commits September 20, 2018 08:55

Merge remote-tracking branch 'origin' into tracing

aa16607

Merge remote-tracking branch 'origin' into tracing

51c20d9

Fix linter issue

24a52c3

prestonvanloon merged commit 2a51ed3 into prysmaticlabs:master Sep 20, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

P2P Message Execution Tracing #517

P2P Message Execution Tracing #517

d1vyank commented Sep 14, 2018 •

edited

Loading

CLAassistant commented Sep 14, 2018 •

edited

Loading

d1vyank Sep 14, 2018

terencechain Sep 14, 2018

d1vyank Sep 17, 2018

prestonvanloon Sep 18, 2018

terencechain left a comment

terencechain Sep 14, 2018

terencechain Sep 14, 2018

terencechain Sep 14, 2018

prestonvanloon left a comment

prestonvanloon Sep 15, 2018

prestonvanloon Sep 15, 2018

prestonvanloon Sep 15, 2018

prestonvanloon Sep 15, 2018

d1vyank commented Sep 17, 2018

prestonvanloon Sep 18, 2018 •

edited

Loading

d1vyank Sep 18, 2018

prestonvanloon Sep 18, 2018

d1vyank Sep 18, 2018

codecov bot commented Sep 19, 2018 •

edited

Loading

prestonvanloon commented Sep 20, 2018


		var log = logrus.WithField("prefix", "tracer")

		// New creates and initializes a new tracing adapter

P2P Message Execution Tracing #517

P2P Message Execution Tracing #517

Conversation

d1vyank commented Sep 14, 2018 • edited Loading

CLAassistant commented Sep 14, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

terencechain left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prestonvanloon left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

d1vyank commented Sep 17, 2018

prestonvanloon Sep 18, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov bot commented Sep 19, 2018 • edited Loading

Codecov Report

prestonvanloon commented Sep 20, 2018

d1vyank commented Sep 14, 2018 •

edited

Loading

CLAassistant commented Sep 14, 2018 •

edited

Loading

prestonvanloon Sep 18, 2018 •

edited

Loading

codecov bot commented Sep 19, 2018 •

edited

Loading