export CHGDISABLE=1

~/hg/hg debugpython << 'EOS'
from timeit import timeit
from bindings import tracing
def nop(): pass
@tracing.wrapfunc
def wrap(): pass
@tracing.wrapfunc
@tracing.meta(lambda: [("color", "blue")])
def wrap_meta(): pass
def 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

"""
Explanation: Tracing
Jun Wu
Tracing Data
Example:
[-----span 1------] &lt;- {"name": "span 1", "module": "a.py", "line": 30, ...}
  [--span 2--]      &lt;- {"name": "span 2", "module": "b.rs", "line": 40, ...}
  ^          ^
  |          |
  |          {"action": "exit-span", .... }
  |
  {"action": "enter-span", "span": "span 2", "timestamp": 10, "tid": 2, ...}
Schema:
rust
struct TracingData { spans: Vec&lt;Span&gt;, events: Vec&lt;Event&gt; }
struct Span        { meta: Map&lt;String, String&gt; }
struct Event       { action: Action, span_id: SpanId, time: Time, pid: u64, tid: u64 }
enum   Action      { EnterSpan, ExitSpan }
Implementation:
rust
struct TracingData { ..., strings: Vec&lt;String&gt; }
struct Span        { meta: Map&lt;StringId, StringId&gt; }
struct Event       { ... }
enum   Action      { ... }
Tracing Integration
Rust, Python, Logging, Visualization
+-------------+                                     +------------+
  |             |  tokio/tracing              Binary  |            |
  |  Rust Code  +-----------------+         +---------&gt;  Blackbox  |
  |             |                 |         |         |            |
  +-------------+                 |         |         +------------+
                              +---v---------v--+
                              |                |
                              |  Tracing Data  |
                              |                |
                              +---^---------+--+
+---------------+                 |         |         +--------------+
|               |    bindings     |         |  JSON   |              |
|  Python Code  +-----------------+         +---------&gt; Chrome Trace |
|               |                                     |              |
+---------------+                                     +--------------+
Tracing in Rust
Proc-macro:
```rust
use tracing::instrument;
[instrument]
fn plus0(a: u8, b: u8) -> u8 {
    a + b
}
```
```rust
[instrument(level = "debug")]
fn plus1(a: u8, b: u8) -> u8 {
    a + b
}
```
Manual:
```rust
use tracing::info_span;
fn plus2(a: u8, b: u8) -> u8 {
   info_span!("plus2", a=a, b=b).in_scope(|| a + b)
}
```
rust
fn plus3(a: u8, b: u8) -&gt; u8 {
   let span = info_span!("plus3", a=a, b=b, result=0);
   let _guard = span.enter();
   let res = a + b;
   span.record("result", &amp;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.
```rust
fn download_files(urls: &[URL]) {
    info_span!("downloading files", count=urls.len()).in_scope(|| {
        urls.iter().for_each(download_single_file)
    })
}
fn download_single_file(url: &URL) {
    debug_span!("downloading file", url=url).in_scope(|| { ... })
}
```
Default trace level is info. To change trace level:
bash
EDENSCM_TRACE_LEVEL=debug ./hg ...
Tracing in Python
Decorator:
```python
from bindings import tracing
@tracing.wrapfunc
def plus1(a, b):
    return a + b
```
Decorator, with extra metadata:
```python
from bindings import tracing
@tracing.wrapfunc
@tracing.meta(lambda a, b: [("a", str(a)), ("b", str(b))])
def plus1(a, b):
    return a + b
```
Manual:
```python
from bindings import tracing
tracer = tracing.singleton
def plus2(a, b):
    spanid = tracer.span([("name", "plus2"), ("a", str(a)), ("b", str(b))])
    tracer.enter(spanid)
    result = a + b
    tracer.edit(spanid, [("result", str(result))])
    tracer.exit(spanid)
    return result
```
Note: No line number or module name recorded automatically.
Tracing Overhead in Python
End of explanation
"""


cat > ~/print << EOF
#!$HOME/hg/hg debugpython
import sys
from bindings import tracing

t = tracing.tracingdata()
with t:
    exec(sys.stdin.read())

if sys.argv[1] == 'ascii':
    min_micros = int(sys.argv[2])
    print(t.ascii(min_micros).strip())
elif sys.argv[1] == 'traceevent':
    import json
    print(json.dumps(t.traceevent(), sort_keys=True, indent=4, separators=(',', ': ')))
else:
    import pprint
    pprint.pprint(t.treespans())
EOF

chmod +x ~/print

"""
Explanation: 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 edenscm.mercurial.eden_dirstate takes 50ms.

If some functions are not cheap to trace, we can blacklist them.
To trace functions in modules automatically (simplified):
python
def tracemodule(mod):
    moddict = mod.__dict__
    for name, item in moddict.items():
        if callable(item):
            moddict[name] = tracing.wrapfunc(item)
To get a chance to trace modules at import time:
```python
PEP 302: Import Hooks. Easier to use than __import__.
class ImportHook(object):
    def find_module(self, fullname):
        import(fullname)  # can also measure import overhead here
        tracemodule(sys.modules[fullname])
        ...
sys.meta_path.insert(0, ImportHook())
```
edenscm.traceimport added to handle automatic tracing. It is enabled right before edenscm.hgdemandimport. 
Python tracing can be turned on via EDENSCM_TRACE_PY:
bash
EDENSCM_TRACE_PY='*' ./hg ...           # (attempt to) trace everything
EDENSCM_TRACE_PY='import' ...           # trace import overhead
EDENSCM_TRACE_PY='import edenscm.*' ... # trace imports, and edenscm modules
Wrapping happens at import time. The importer is changed at edenscm.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.)
End of explanation
"""


~/print ascii 0 << 'EOS'

@tracing.wrapfunc
def fib(x):
    return x if x <= 2 else fib(x - 1) + fib(x - 2)

fib(5)
EOS

"""
Explanation: The ASCII Format
Accurate recursive call graph (like traceprof).
End of explanation
"""


~/print ascii 0 << 'EOS'

@tracing.wrapfunc
@tracing.meta(lambda x: [("x", str(x))])
def fib(x):
    return x if x <= 2 else fib(x - 1) + fib(x - 2)

fib(4)
EOS

"""
Explanation: Annotated metadata (like perftrace)
End of explanation
"""


~/print ascii 50000 << 'EOS'
import time

sleep = tracing.wrapfunc(time.sleep)

for i in range(10):
    sleep(0.01)
EOS

"""
Explanation: Call counts (like traceprof)
End of explanation
"""


~/print treespans 0 << 'EOS'

@tracing.wrapfunc
def fact(x):
    return x if x <= 1 else x * fact(x - 1)

fact(2)
EOS

"""
Explanation: The Tree Spans Format
Used internally by the ASCII render.
End of explanation
"""


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

"""
Explanation: 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)
End of explanation
"""


