Adding LTTng-UST tracing support

[FrancisDeslauriers]

BPO	28909
Nosy	@jcea, @cburroughs, @ambv, @pdmccormick, @stratakis
Files	0001-Add-LTTng-UST-probe-and-tracepoints.patch: Add lttng-ust support patch v1 0002-LTTng-UST-tracing-tests.patch: LTTng UST test patch v1 0003-Documentation-of-LTTng-UST-tracing-instrumentation.patch: LTTng UST Documentation patch v1 bpo-28909-pyprobe-refactor-20180727.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/ambv'
closed_at = None
created_at = <Date 2016-12-08.20:04:34.910>
labels = ['type-feature', '3.8']
title = 'Adding LTTng-UST tracing support'
updated_at = <Date 2018-07-27.06:38:18.269>
user = 'https://bugs.python.org/FrancisDeslauriers'

bugs.python.org fields:

activity = <Date 2018-07-27.06:38:18.269>
actor = 'pdmccormick'
assignee = 'lukasz.langa'
closed = False
closed_date = None
closer = None
components = []
creation = <Date 2016-12-08.20:04:34.910>
creator = 'Francis Deslauriers'
dependencies = []
files = ['45802', '46694', '46695', '47715']
hgrepos = ['367']
issue_num = 28909
keywords = ['patch']
message_count = 14.0
messages = ['282733', '284208', '285074', '288103', '288110', '288315', '288489', '288492', '288896', '288897', '292074', '301997', '321769', '322467']
nosy_count = 6.0
nosy_names = ['jcea', 'cburroughs', 'lukasz.langa', 'pdmccormick', 'cstratak', 'Francis Deslauriers']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue28909'
versions = ['Python 3.8']

[FrancisDeslauriers]

This patch extends the tracing infrastructure to support LTTng UserSpace
Tracer. Using LTTng-UST, users would have access to a low overhead tracing
done entirely from userspace.

Depending on the tracing configure option used (none, --with-dtrace or
--with-lttngust) macros will be expanded to probes and tracepoints of the
desired tracer if any. Only the needed instrumentation will be added to the
binary. This technique is used to different degrees by other projects like
Qemu[1] and Node.js[2].

I attached a patch adding this feature. I tested the changes and the
instrumentation on LTTng-UST and SystemTap on Ubuntu 16.04. I would
appreciate if someone could test those changes on macOS and other
platforms supporting USDT probes.

[1]https://github.com/qemu/qemu/blob/master/configure#L4303
[2]https://github.com/nodejs/node/blob/master/configure#L811

[ambv]

This looks promising but I don't know how to test it. Tests would be welcome, as well as some explanation what OS and kernel I need to use to test it out.

Why does your patch rename the DTrace provider from "python" to "cpython"? At this point, with release of Python 3.6, it's an incompatible change we can't really accept easily.

[FrancisDeslauriers]

Thanks Łukasz,
I will add tests following the example of the DTrace tests and update the Doc/howto/instrumentation.rst file to include this new information.

LTTng can be used on all major Linux distros (Ubuntu, Debian, Fedora, etc.) either from distribution packages or compiled from source. It runs on kernels that came out after 2.6.27.

You are right, I should have explained why I changed the provider name. I changed it be as specific as possible to avoid potential name clash with other Python interpreters.
I will send an updated patch that keeps the old name given that it was already released.

[pdmccormick]

Fork at <https://github.com/pdmccormick/cpython/tree/bpo-28909-adding-lttng-ust\> with Francis' original patch, plus a revert for the DTrace provider name change.

Here are instructions I used to try this out:

## LTTng installation

Full installation instructions for LTTng are available at https://lttng.org/download/. On Ubuntu 19.04 you can currently install LTTng v2.7 from the universe repository if it is enabled:

$ apt-get install lttng-tools lttng-modules-dkms liblttng-ust-dev babeltrace

## Building

Clone/fetch/checkout from <https://github.com/pdmccormick/cpython/tree/bpo-28909-adding-lttng-ust\> and run:

$ ./configure --with-lttngust
$ make

## Tracing a session

LTTng operates around the concept of tracing selected userspace & kernelspace events of interest within the context of a session, so let's start one and run the instrumented interpreter to see what happens:

$ lttng create 'pysession'
$ lttng enable-event --userspace 'cpython:*'
$ lttng start
$ ./python -m this
$ lttng stop
$ lttng view | wc -l
48257
$ lttng view
[23:50:04.493873655] (+?.?????????) keflavik cpython:gc__start: { cpu_id = 1 }, { generation = 0 }
[23:50:04.493910472] (+0.000036817) keflavik cpython:gc__done: { cpu_id = 1 }, { collected = 0 }
[23:50:04.494281326] (+0.000370854) keflavik cpython:gc__start: { cpu_id = 1 }, { generation = 0 }
[23:50:04.494305307] (+0.000023981) keflavik cpython:gc__done: { cpu_id = 1 }, { collected = 0 }
[23:50:04.495031049] (+0.000725742) keflavik cpython:gc__start: { cpu_id = 1 }, { generation = 0 }
[23:50:04.495074272] (+0.000043223) keflavik cpython:gc__done: { cpu_id = 1 }, { collected = 0 }
[23:50:04.495403759] (+0.000329487) keflavik cpython:function__entry: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "<module>", line_no = 8 }
[23:50:04.495405056] (+0.000001297) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "<module>", line_no = 8 }
[23:50:04.495406486] (+0.000001430) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "<module>", line_no = 25 }
[23:50:04.495407149] (+0.000000663) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "<module>", line_no = 27 }
[23:50:04.495408921] (+0.000001772) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "<module>", line_no = 35 }
[23:50:04.495409618] (+0.000000697) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "<module>", line_no = 42 }
[23:50:04.495410775] (+0.000001157) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "<module>", line_no = 44 }
[23:50:04.495412006] (+0.000001231) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "<module>", line_no = 47 }
[23:50:04.495421990] (+0.000009984) keflavik cpython:function__entry: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "_DeadlockError", line_no = 47 }
[23:50:04.495422496] (+0.000000506) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "_DeadlockError", line_no = 47 }
[23:50:04.495423317] (+0.000000821) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "_DeadlockError", line_no = 48 }
[23:50:04.495424559] (+0.000001242) keflavik cpython:function__return: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "_DeadlockError", line_no = 48 }
[23:50:04.495468551] (+0.000043992) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "<module>", line_no = 51 }
[23:50:04.495470096] (+0.000001545) keflavik cpython:function__entry: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "_ModuleLock", line_no = 51 }
[23:50:04.495470570] (+0.000000474) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "_ModuleLock", line_no = 51 }
[23:50:04.495471249] (+0.000000679) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "_ModuleLock", line_no = 55 }
[23:50:04.495471746] (+0.000000497) keflavik cpython:line: { cpu_id = 1 }, { co_filename = "<frozen importlib._bootstrap>", co_name = "_ModuleLock", line_no = 57 }
...

The raw trace files will be written under ~/lttng-traces/pysession-$TIMESTAMP. To clean them up afterwards, you can run:

$ lttng destroy

## GitHub

I would be happy to re-post this to GitHub issues if so desired.

[pdmccormick]

A few suggestions:

• Disallow --with-lttngust on anything other than Linux (on macOS configure dies due to differences in acceptable mktemp arguments if you even attempt it)
• Rename cpython_inst.h to pytrace.h and rename pylttngust_probes.h to pytrace_lttngust_probes.h
  • While we're at it, rename pydtrace.h to pytrace_dtrace.h, and other mentions of PyDTrace_* to PyTrace_DTrace_*?
• Define a WITH_TRACE or Py_TRACE or similar preprocessor symbol
• Using that symbol, in [Python/ceval.c](https://github.com/python/cpython/blob/main/Python/ceval.c) ifdef-guard the static function prototypes and function calls
  • Otherwise when BOTH DTrace and LTTng-UST are disabled, Clang on macOS gives warning: code will never be executed warnings on the various arms of the if (PyTraceEnabled(...)) statements, and GCC on Linux warn about unused variables lineno, funcname and filename in pytrace_function_{entry,return}, since the actual use of those variables as arguments is preprocessed out of existance

If everyone was in agreement, would it make sense to sequence this as first the generalization-renames to the existing DTrace/SystemTap code, and then recast the LTTng addition patch on top of those? I'd be happy to do this.

So, PyTrace or PyTracing?

[ambv]

Thanks for working on this! A few thoughts.

1. Keep the existing names.

"PyTrace" is already a name in use for a different purpose. I understand the itch to make the name more "right" but I am in general not a fan of renaming "PyDTrace" to anything else now. It was a placeholder from day one (SystemTap uses it, too, after all). So, looking closer at the patch now I'd prefer us to keep all existing names and add LTTng as another alternative engine here. That will make the patch much shorter.

A nit: the name LTTng-UST is rather unfriendly, especially when used without the dash and in all lowercase characters. Given that we're using "dtrace" and "systemtap", it would be simpler to just use "lttng" (drop the "-ust").

2. DTrace vs SystemTap vs LTTng.

It's impossible to have DTrace and SystemTap at the same time, so it was natural to choose to auto-detect the engine. With LTTng it becomes less obvious what the configure options should be.

Should it be possible at all to have *both* LTTng and SystemTap compiled in at the same time? Does this make sense?

If yes, then keeping --with-dtrace and --with-lttng as separate options makes sense to me. If it doesn't, we should change the option to look like this: --with(out)-dtrace=[=detect]. This way people could pass the following:

--without-dtrace (the default)
--with-dtrace  (detects DTrace or SystemTap or LTTng, in that order)
--with-dtrace=detect  (like the one above)
--with-dtrace=dtrace  (assumes DTrace, fails if cannot proceed)
--with-dtrace=systemtap  (assumes SystemTap, fails if cannot proceed)
--with-dtrace=lttng  (assumes LTTng, fails if cannot proceed)  

3. Other questions.

Clang on macOS gives warning: code will never be executed warnings on the various arms of the if (PyTraceEnabled(...)) statements, and GCC on Linux warn about unused variables lineno, funcname and filename in pytrace_function_{entry,return}, since the actual use of those variables as arguments is preprocessed out of existance.

Do you get unused code warnings without your patch applied? I don't.

I would be happy to re-post this to GitHub issues if so desired.

CPython is not using GitHub issues.

[FrancisDeslauriers]

I am finally having the time to work in this.

A nit: the name LTTng-UST is rather unfriendly, especially when used without the dash and in all lowercase characters. Given that we're using "dtrace" and "systemtap", it would be simpler to just use "lttng" (drop the "-ust").
We can certainly drop the "-ust" and have the name in lowercase.

It's impossible to have DTrace and SystemTap at the same time, so it was natural to choose to auto-detect the engine. With LTTng it becomes less obvious what the configure options should be.
Should it be possible at all to have both LTTng and SystemTap compiled in at the same time? Does this make sense?
It's possible to have both SystemTap and LTTng in the same binary. LTTng-UST has a configure option --with-sdt to include a SystemTap SDT probe alongside each LTTng-UST tracepoint. I don't have a specific usecase in mind but I can picture a setup where a binary is instrumented with both frameworks and the users either decide to use the low overhead tracing of LTTng or the versatile runtime aggregation of SystemTap depending on the problem they are trying to diagnose. So I think keeping both configure options makes sense.

Do you get unused code warnings without your patch applied? I don't.
I am getting those errors too on Linux with GCC. I will make sure to fix them in the next round.

I am currently working on the tests and documentation and I hope to submit patches for review early next week.

Thank you,
Francis

[pdmccormick]

Hi Łukasz, thank you for the feedback!

"PyTrace" is already a name in use for a different purpose. I understand the
itch to make the name more "right" but I am in general not a fan of renaming
"PyDTrace" to anything else now. It was a placeholder from day one (SystemTap
uses it, too, after all). So, looking closer at the patch now I'd prefer us
to keep all existing names and add LTTng as another alternative engine here.
That will make the patch much shorter.

What about PyProbe? Given the multitude of tools and techniques in this space, wouldn't it be worthwhile to clarify things before adding this? I think conflating dtrace and lttng would only lead to more confusion for users as they really are distinct technologies.

Apart from the --with{out)-dtrace configure options, are these terms exposed to users anywhere else? I agree that those options shouldn't be changed now.

[FrancisDeslauriers]

What about PyProbe? Given the multitude of tools and techniques in this space, wouldn't it be worthwhile to clarify things before adding this? I think conflating dtrace and lttng would only lead to more confusion for users as they really are distinct technologies.

I like the PyProbe name too. PyTracepoint could be another option.

Here is the tests patch. The tests are using the same test cases as the DTrace and SystemTap tests.
It still uses the same name as before and the tests were added to the existing test_dtrace.py file. I will send an updated version once we have the final name.

[FrancisDeslauriers]

Here is the documentation patch.

[stratakis]

Just a small note here for the documentation patch.

yum is deprecated in Fedora, and dnf is now the default package manager, so the respective instructions for Fedora should reflect that.

[FrancisDeslauriers]

Hi all,
Is there anything I can do to move this patch-set forward?

@charalampos, I will make sure to include this in the patch. Thank you.

[FrancisDeslauriers]

Hi all,

It seems that, as of right now, the thing blocking this patchset from
going forward is the name of the intrumentation point.

Two naming approached were suggested:
- Keeping PyDtrace*
- Changing to PyProbe*

I prefer the PyProbe option as it's a more generic name and is not misleading
of the underlying tracing engine but if people prefer that we keep the PyDtrace
version let's go with that.
So, what should we go with?

I can easily update and rebase this patchset.

As an example of how this feature could be used, a colleague of mine gave a
talk1 at PyCon Canada 2017 about tracing Python applications using this
patchset. He built a tool to visualize Python Logging, Python function calls
and Linux syscalls all in the same view. This was done using the existing
Python logger tracing of LTTng-UST, the LTTng kernel tracer and the CPython
LTTng-UST instrumentation of this patchset. Here is an asciinema2 recording
used in the talk, it shows the tool in action.

Cheers!
Francis

[pdmccormick]

I would like to propose the following patch[0] which generalizes the PyDTrace_* definitions to a more generic PyProbe structure, in anticipation of including LTTng support side-by-side with the existing DTrace support.

A couple of argument types in [Include/pydtrace.h](https://github.com/python/cpython/blob/main/Include/pydtrace.h) were also changed to match those in [Include/pydtrace.d](https://github.com/python/cpython/blob/main/Include/pydtrace.d). I can split that out to a separate, pre-PyProbe patch if that would be preferred.

Some of the *_ENABLED() calls were reorganized such that they will actually be invoked twice (specifically in [Python/ceval.c](https://github.com/python/cpython/blob/main/Python/ceval.c) were the enabled check was used prior to calling helper functions, which then eventually invoked the DTrace macros.) If this won't work, we could add a sequence of guarded-by-ifdef-instead-of-enabled calls to ensure that there will only ever be one instance of any given PyDTrace_*_ENABLED() call.

I've tested compilation on macOS with and without DTrace configured.

Feedback and comments would be most welcome!

Thanks,
Peter

[0] https://github.com/pdmccormick/cpython/commit/1e399f5ec381276b52e6a4f5a755fc0f23bd6d97
[1] https://github.com/pdmccormick/cpython/tree/bpo-28909-pyprobe-refactor