Tracing¶

Jun Wu

Tracing Data¶

Example:

[-----span 1------] <- {"name": "span 1", "module": "a.py", "line": 30, ...}
  [--span 2--] <- {"name": "span 2", "module": "b.rs", "line": 40, ...}
  ^ ^
  | |
  | {"action": "exit-span", .... }
  |
  {"action": "enter-span", "span": "span 2", "timestamp": 10, "tid": 2, ...}

Schema:

structTracingData { spans:Vec\<Span\>, events:Vec\<Event\> }structSpan{ meta:Map\<String, String\> }structEvent{ action:Action, span\_id:SpanId, time:Time, pid:u64, tid:u64}enumAction{ EnterSpan, ExitSpan }

Implementation:

structTracingData { ..., strings:Vec\<String\> }structSpan{ meta:Map\<StringId, StringId\> }structEvent{ ... }enumAction{ ... }

Tracing Integration¶

Rust, Python, Logging, Visualization

+-------------+ +------------+
  | | tokio/tracing Binary | |
  | Rust Code +-----------------+ +---------> Blackbox |
  | | | | | |
  +-------------+ | | +------------+
                              +---v---------v--+
                              | |
                              | Tracing Data |
                              | |
                              +---^---------+--+
+---------------+ | | +--------------+
| | bindings | | JSON | |
| Python Code +-----------------+ +---------> Chrome Trace |
| | | |
+---------------+ +--------------+

Tracing in Rust¶

Proc-macro:

use tracing::instrument;#[instrument]fnplus0(a:u8, b:u8) ->u8{a + b}

#[instrument(level = "debug")]fnplus1(a:u8, b:u8) ->u8{a + b}

Manual:

use tracing::info\_span;fnplus2(a:u8, b:u8) ->u8{info\_span!("plus2", a=a, b=b).in\_scope(|| a + b)}

fnplus3(a:u8, b:u8) ->u8{let span = info\_span!("plus3", a=a, b=b, result=0);let \_guard = span.enter();let res = a + b;span.record("result", &res);res}

Tracing Overhead in Rust¶

By reading tokio/tracing source code:

If a span is disabled, the overhead is a lock-free integer "eq" check (in one word: cheap).
If a span is enabled, the overhead probably involves some locking, memory lookups / cache misses, etc (in one word: expensive).

Good practise: Use info for summary. Use debug for loop body.

fndownload\_files(urls:&[URL]) {info\_span!("downloading files", count=urls.len()).in\_scope(|| {urls.iter().for\_each(download\_single\_file)})}fndownload\_single\_file(url:&URL) {debug\_span!("downloading file", url=url).in\_scope(|| { ... })}

Default trace level is info. To change trace level:

EDENSCM\_TRACE\_LEVEL=debug ./hg ...

Tracing in Python¶

Decorator:

[email protected](a,b):returna+b

Decorator, with extra metadata:

[email protected]@tracing.meta(lambdaa,b:[("a",str(a)),("b",str(b))])defplus1(a,b):returna+b

Manual:

frombindingsimporttracingtracer=tracing.singletondefplus2(a,b):spanid=tracer.span([("name","plus2"),("a",str(a)),("b",str(b))])tracer.enter(spanid)result=a+btracer.edit(spanid,[("result",str(result))])tracer.exit(spanid)returnresult

Note: No line number or module name recorded automatically.

Tracing Overhead in Python¶

In [2]:

~/hg/hg debugpython\<\< 'EOS'from timeit import timeitfrom bindings import tracingdef nop(): [email protected] wrap(): [email protected]@tracing.meta(lambda: [("color", "blue")])def wrap\_meta(): passdef bindings(tracer=tracing.singleton): id = tracer.span([("name", "bindings")]); tracer.enter(id); tracer.exit(id)base = timeit(nop, number=10000)for f in [nop, wrap, wrap\_meta, bindings]: duration = timeit(f, number=10000) print("{:\>6.1f}x {:\>6.0f}ns # {}".format(duration / base - 1, (duration - base) \* 1e5, f.\_\_name\_\_))EOS

0.0x 0ns # nop
   3.4x 266ns # wrap
  12.9x 998ns # wrap_meta
  24.5x 1895ns # bindings

Trace-Them-All as a Profiler¶

It could be affordable:

wrapfunc has 300ns overhead per Python function call.
A command like hg sl can take 1 second. It has 200k calls.
If all functions are wrapped, the overhead of hg sl is 60ms, or 6%.
As a comparison, import sapling.eden_dirstate takes 50ms.

If some functions are not cheap to trace, we can blacklist them.

sapling.traceimport added to handle automatic tracing. It is enabled right before sapling.hgdemandimport.

Python tracing can be turned on via EDENSCM_TRACE_PY:

EDENSCM\_TRACE\_PY='\*'./hg ...# (attempt to) trace everythingEDENSCM\_TRACE\_PY='import'...# trace import overheadEDENSCM\_TRACE\_PY='import sapling.\*'...# trace imports, and sapling modules

Wrapping happens at import time. The importer is changed at sapling.run, before enabling demandimport.

Python Profiler / Tracing Feature Matrix¶

	statprof	traceprof	perftrace	tracing
Profiler Overhead	Low	14%	-	6%
High Precision	No	Yes	Yes	Yes
Auto Instructment	Yes	Yes	No	Yes
Include Line Numbers	Yes	Yes	No	Yes
Call Count	No	Yes	Yes	Yes
Trace Rust Code	No	No	No	Yes
Trace Imports	No	No	No	Yes
Metadata Annotations	No	No	Yes	Yes
Clean Traceback	Yes	Yes	No	Yes
Trace Multi-threads	No	No	No	Yes
Deserialization	Yes	No	No	Yes
ASCII Visualizer	Yes	Yes	Yes	Yes
Chrome Visualizer	Yes	No	No	Yes
Merge Traces	No	No	No	Yes
"No"s	7	7	9	0

Output Formats¶

ASCII
Trace Event: serde::Serialize (which can be converted to JSON, CBOR, PyObject, etc.)
Tree Spans: serde::Serialize (which can be converted to PyObject, etc.)

The ASCII Format¶

Accurate recursive call graph (like traceprof).

In [4]:

~/print ascii0\<\< 'EOS'@tracing.wrapfuncdef fib(x): return x if x \<= 2 else fib(x - 1) + fib(x - 2)fib(5)EOS

Process 2366865 Thread 2366865:
Start Dur.ms | Name Source
    0 +0 | __main__.fib __main__ line 2
    0 +0 \ __main__.fib __main__ line 2
    0 +0 \ __main__.fib __main__ line 2
    0 +0 \ __main__.fib __main__ line 2
    0 +0 \ __main__.fib __main__ line 2
    0 +0 \ __main__.fib __main__ line 2
    0 +0 \ __main__.fib __main__ line 2
    0 +0 | __main__.fib __main__ line 2
    0 +0 | __main__.fib __main__ line 2

Annotated metadata (like perftrace)

In [5]:

~/print ascii0\<\< 'EOS'@[email protected](lambda x: [("x", str(x))])def fib(x): return x if x \<= 2 else fib(x - 1) + fib(x - 2)fib(4)EOS

Process 2366892 Thread 2366892:
Start Dur.ms | Name Source
    0 +0 | __main__.fib __main__ line 2
             | - x = 4 :
    0 +0 \ __main__.fib __main__ line 2
               | - x = 3 :
    0 +0 \ __main__.fib __main__ line 2
                | - x = 2 :
    0 +0 \ __main__.fib __main__ line 2
                | - x = 1 :
    0 +0 \ __main__.fib __main__ line 2
               | - x = 2 :

Call counts (like traceprof)

In [6]:

~/print ascii50000\<\< 'EOS'import timesleep = tracing.wrapfunc(time.sleep)for i in range(10): sleep(0.01)EOS

Process 2366912 Thread 2366912:
Start Dur.ms | Name Source
    0 +101 | time.sleep (10 times) time line None

The Tree Spans Format¶

Used internally by the ASCII render.

In [7]:

~/print treespans0\<\< 'EOS'@tracing.wrapfuncdef fact(x): return x if x \<= 1 else x \* fact(x - 1)fact(2)EOS

{(2366997, 2366997): [{'children': [1], 'duration': 0, 'start': 0},
                      {'children': [2],
                       'duration': 3,
                       'line': '2',
                       'module_path': ' __main__',
                       'name': ' __main__.fact',
                       'start': 137},
                      {'children': [],
                       'duration': 1,
                       'line': '2',
                       'module_path': ' __main__',
                       'name': ' __main__.fact',
                       'start': 138}]}

The Trace Event Format¶

Format specification: https://github.com/catapult-project/catapult/wiki/Trace-Event-Format.

Supported By:

Chrome about:tracing
Chrome DevTools - Performance
https://www.speedscope.app (might render incorrectly: https://github.com/jlfwong/speedscope/issues/223)

In [8]:

echo'tracing.wrapfunc(id)(1)'|~/print traceevent

{
    "displayTimeUnit": "ms",
    "otherData": {},
    "traceEvents": [
        {
            "args": {
                "line": "None",
                "module_path": " __builtin__"
            },
            "cat": "default",
            "name": " __builtin__.id",
            "ph": "B",
            "pid": 2366999,
            "tid": 2366999,
            "ts": 73
        },
        {
            "args": {
                "line": "None",
                "module_path": " __builtin__"
            },
            "cat": "default",
            "name": " __builtin__.id",
            "ph": "E",
            "pid": 2366999,
            "tid": 2366999,
            "ts": 74
        }
    ]
}

Chrome about:tracing:

Chrome DevTools -> Performance.

Exporting Tracing Data¶

Single command. Use EDENSCM_TRACE_OUTPUT:

exportCHGDISABLE=1EDENSCM\_TRACE\_OUTPUT=a.txt ./hg ...EDENSCM\_TRACE\_OUTPUT=a.json ./hg ...EDENSCM\_TRACE\_OUTPUT=a.json.gzEDENSCM\_TRACE\_PY='import sapling.\*'EDENSCM\_TRACE\_LEVEL=debug ./hg ...

Traces are also logged in blackbox. Use hg dump-trace to merge and export them:

hg dump-trace -o a.json.gz -t'since 15 minutes ago'

Tracing for Better Testing¶

Examples:

Expect a template rendering function to be called N times, under another function. How can I test it?
Expect a network fetch function to not fetch foo/bar. How can I test it?

Today, in .t tests:

$ hg show X --debug
  ...
  12 files fetched over 1 fetches - (12 misses, 0.00% hit ratio) over 0.00s

In Python tests:

t=tracing.tracingdata()witht:sh%"hg amend"# code to testassertt.treespans()...# check spans

In Rust:

let data = Arc::new(Mutex::new(TracingData::new()));let collector = TracingCollector::new(data.clone(), Level::DEBUG);tracing::subscriber::with\_default(collector, || {... // code to test});data.lock().tree\_spans();// check spans

Goodies¶

Date Parsing¶

lib/hgtime:

Compatible with formats specified by hg help dates.
Support ... ago human-readable formats.

Examples:

let time1 = hgtime::HgTime::parse("Oct 1");let time2 = hgtime::HgTime::parse("5 minutes ago");let time\_range1 = hgtime::HgTime::parse("since 10m ago");let time\_range2 = hgtime::HgTime::parse("Oct 1 to Oct 2");let time\_range3 = hgtime::HgTime::parse("Apr 2019");// Apr 1, 2019 to Apr 30, 2019

Mincode: Fast, Compat Serde Serialization¶

lib/mincode

Similar to bincode. But uses VLQ for integers to save spaces.
Compact and fast. Suitable for stable structures. See D17087352 for benchmark.
If you consider serde_cbor::ser::to_*_packed to reduce size, most likely mincode is a better choice.
@wez has also reinvented the same thing as varbincode.

Convert serde values to Python objects¶

lib/cpython-ext

Anything that implements serde::Serialize can be converted to Python objects trivially and efficiently.

let mut map = HashMap::\<u32, u32\>::new();// Invalid JSON map.insert(1, 2);let obj = cpython\_ext::ser::to\_object(py, &map)?;

Rust Subcommands¶

lib/hgcommands

table.register(foo\_bar, "foo-bar", "...");

Supported syntax:

hg foo-bar
hg foo --bar
hg foo bar (if hg foo is not a command)

Also works for aliases.

Potential goal: move hacky flags away from main commands. For example, diff --since-last-submit, and amend --fixup.

Tracing non-hg programs¶

hg debugpython --trace 'sapling.*' python-script.py can be used to do ad-hoc analysis.

Tracing¶

Tracing¶

Tracing Data¶

Tracing Integration¶

Tracing in Rust¶

Tracing Overhead in Rust¶

Tracing in Python¶

Tracing Overhead in Python¶

Trace-Them-All as a Profiler¶

Python Profiler / Tracing Feature Matrix¶

Output Formats¶

The ASCII Format¶

The Tree Spans Format¶

The Trace Event Format¶

Exporting Tracing Data¶

Tracing for Better Testing¶

Goodies¶

Date Parsing¶

Mincode: Fast, Compat Serde Serialization¶

Convert serde values to Python objects¶

Rust Subcommands¶

Tracing non-hg programs¶

Future Plans¶

You can help! ¶

Demo / QA