Tracing - Implement feature to record values with span creation

[mattrutherford]

Allow recording values along with new spans to capture useful information such as function arguments. This may be useful in cases where execution time is dependant on input values.

Currently only the Log and Telemetry Receivers actually use the values. It may also be possible to use with Grafana, but need to find the best way to handle this.

We do not currently support recording values after span creation. If we require this then I would prefer to make a follow-up PR to implement it.

[parity-cla-bot]

It looks like @mattrutherford signed our Contributor License Agreement. 👍

Many thanks,

Parity Technologies CLA Bot

[gavofyork]

Can we record textual tags in the same way to annotate a timeseries?

[mattrutherford]

Can we record textual tags in the same way to annotate a timeseries?

Currently we're able to collect key = value pairs at the time of span creation (local variables may be used as field values without an assignment), and all end up as string, (but type can be anything that is Debug ). If you want a way to add these tags externally, then it's possible we could use events perhaps.

Also might be of interest that I had planned to allow effectively the same thing in substrate-analytics, the difference being the tags would be added there and persisted to the DB, able to be cross referenced with the tracing output received from substrate (telemetry).

[mattrutherford]

To illustrate the output format for the new values:

With the following span in client.rs

let span = tracing::span!(
	tracing::Level::INFO,
	"execute_and_import_block",
	?hash,
	?origin,
	finalized,
	enact_state
);

Output to log:

2019-11-29 09:16:48 TRACING: INFO substrate_client::client: execute_and_import_block, line: 834, time: 82048535, hash=0xc84c49af040b997f609f75a8c801e6f50d49e7af86de78eaad22b835f5f6fc5c, origin=Own, finalized=false, enact_state=true
2019-11-29 09:16:51 TRACING: INFO substrate_client::client: execute_and_import_block, line: 834, time: 85457108, hash=0x3ee9a71fea7b7748829ab2050341a729d54ec0479ac27ee3a1163d8642cc3b32, origin=Own, finalized=false, enact_state=true
2019-11-29 09:16:54 TRACING: INFO substrate_client::client: execute_and_import_block, line: 834, time: 86310760, hash=0xae2c7f306b510906f92c682906c6ec58aa34f83325adbbc98fb23ff8dd1f6a7b, origin=Own, finalized=false, enact_state=true
2019-11-29 09:16:57 TRACING: INFO substrate_client::client: execute_and_import_block, line: 834, time: 528942, hash=0xb30aa5e8b4679d8592d5a8c7b81d07a23218a291783e5ba3f4b11475157049b1, origin=Own, finalized=false, enact_state=true
2019-11-29 09:17:00 TRACING: INFO substrate_client::client: execute_and_import_block, line: 834, time: 98606881, hash=0xb8c824feeae9e1c6dce556368446f93b02bad31509b570919e46f47d5acde254, origin=Own, finalized=false, enact_state=true
2019-11-29 09:17:03 TRACING: INFO substrate_client::client: execute_and_import_block, line: 834, time: 88739381, hash=0x82c9b4636770806c86dd30dd717e8c1295fe4b7e429d187049e819054471aa91, origin=Own, finalized=false, enact_state=true

Telemetry:

{
   "ts":"2019-11-29T09:18:18.235576+00:00",
   "msg":"tracing.profiling",
   "line":834,
   "name":"execute_and_import_block",
   "time":"102156634",
   "level":"INFO",
   "target":"substrate_client::client",
   "values":{
      "hash":"0x21d3df5905c81260d61a16b429d93b37b96169330c27d41836a3de6ca66fdf6e",
      "origin":"Own",
      "finalized":"false",
      "enact_state":"true"
   }
}

[marcio-diaz]

lgtm

[gavofyork]

CI failing.