Java filter notification mechanism #11

ghost · 2015-09-01T20:44:04Z

New tests were added to https://github.com/alexmonthy/ust-java-tests to cover the new functionality. Corresponding CI run at: https://ci.lttng.org/view/alexmonthy/job/ust-java-tests-staging-alexmonthy/45/

ghost · 2015-09-01T20:51:02Z

Note this does not include the "filter string" element of event rules, because the sessiond does not currently send it. I will do another patch to add the filter string once it's added on the lttng-tools side.

ghost · 2015-09-02T18:11:20Z

I have pushed a new version of the branch.

Changes since the previous version:

Renamed LogLevelFilter -> LogLevelSelector
Renamed FilterNotificationManager -> FilterChangeNotifier (more in line with IFilterChangeListener)
Clarified the if/elseif's in equals() methods. Now with more brackets.
Listeners now receive the current state upon registration
Made the whole notifier synchronized

Also added a test to verify the "statedump" to the test suite.
Latest run: https://ci.lttng.org/view/alexmonthy/job/ust-java-tests-staging-alexmonthy/46/

ghost · 2015-09-11T05:19:09Z

Thanks for the review! I've fixed the comments, and as we discussed, I added in here the patch to update to the 1.1 agent protocol. This PR is now dependant on lttng/lttng-tools#42 getting into tools first.

ghost · 2015-09-13T23:20:33Z

Update to the latest commit: the protocol version is now 2.0, and it should handle the (hopefully rare) case where the filter string length is between 2^31 and 2^32.

compudj · 2015-09-14T00:51:29Z

----- On Sep 13, 2015, at 7:20 PM, alexmonthy [email protected] wrote:

Update to the latest commit: the protocol version is now 2.0, and it should
handle the (hopefully rare) case where the filter string length is between 2^31
and 2^32.
Did you test that the conversion don't sign-extend when casting
to 64-bit signed integer ?

Why are two arrays needed ?

Thanks,

Mathieu

—
Reply to this email directly or view it on GitHub .

Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

ghost · 2015-09-14T01:24:04Z

On 2015-09-13 08:51 PM, Mathieu Desnoyers wrote:

----- On Sep 13, 2015, at 7:20 PM, alexmonthy [email protected] wrote:

Update to the latest commit: the protocol version is now 2.0, and it should
handle the (hopefully rare) case where the filter string length is between 2^31
and 2^32.
Did you test that the conversion don't sign-extend when casting
to 64-bit signed integer ?

I tested the "usual" case, and the length and string are read correctly.

I have not yet tested the case where the filter string is greater than 2
GB, but I'm planning to add a test for that.

Why are two arrays needed ?

You can't have [] arrays with long indexes in Java, only (signed) int is
permitted. For the case where the total length is greater than
Integer.MAX_VALUE (2^31 - 1) we have to do two separate calls to
ByteBuffer.get(byte[]).

Thanks,

Mathieu

—
Reply to this email directly or view it on GitHub .

compudj · 2015-09-14T14:38:38Z

----- On Sep 13, 2015, at 9:24 PM, alexmonthy [email protected] wrote:

On 2015-09-13 08:51 PM, Mathieu Desnoyers wrote:

----- On Sep 13, 2015, at 7:20 PM, alexmonthy [email protected] wrote:

Update to the latest commit: the protocol version is now 2.0, and it should
handle the (hopefully rare) case where the filter string length is between 2^31
and 2^32.
Did you test that the conversion don't sign-extend when casting
to 64-bit signed integer ?

I tested the "usual" case, and the length and string are read correctly.

I have not yet tested the case where the filter string is greater than 2
GB, but I'm planning to add a test for that.

Why are two arrays needed ?

You can't have [] arrays with long indexes in Java, only (signed) int is
permitted. For the case where the total length is greater than
Integer.MAX_VALUE (2^31 - 1) we have to do two separate calls to
ByteBuffer.get(byte[]).
We'd actually need 2^32 arrays in the worst case, not 2.

Hrm, considering all those limitations, it might make sense to impose
a rather large limit on the string length.

Thoughts ?

Thanks,

Mathieu

Thanks,

Mathieu

—
Reply to this email directly or view it on GitHub .

—
Reply to this email directly or view it on GitHub .

Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

ghost · 2015-09-14T16:40:47Z

You can't have [] arrays with long indexes in Java, only (signed) int is
permitted. For the case where the total length is greater than
Integer.MAX_VALUE (2^31 - 1) we have to do two separate calls to
ByteBuffer.get(byte[]).
We'd actually need 2^32 arrays in the worst case, not 2.

Hrm, considering all those limitations, it might make sense to impose
a rather large limit on the string length.

Thoughts ?

Yes, in fact it turns out that since String is backed by a char[], a
single String can't have more than (2^32 -1) characters either. So I
think that should be the upper limit on what the Java agent supports.

So, should the Java agent check for the length, and return a command
error if the filter string is too long? Or would there be a guaranteed
size limit on the sessiond side too?

ghost · 2015-09-14T17:11:39Z

After discussion, we've decided to put a limit on the size of the filter string. With the new version, if the length is too long, the agent will return a command error.

This allows defining a default behavior for the getBytes() method. That behavior consists of only returning the integer return code, which is what most (but not all) subclasses use. Signed-off-by: Alexandre Montplaisir <[email protected]>

Decouple the TCP client from the implementation of the LTTng Java agent. Instead of using AbstractLttngAgent directly, the TCP client (and the command subclasses) can deal with the new ILttngTcpClientListener interface. The agent will implement this interface. This will also allow easier testing of the TCP client and its protocol, since test classess can now implement their own listener and verify the contents of each command. Signed-off-by: Alexandre Montplaisir <[email protected]>

Instead of just tracking which event names are enabled in the tracing session, we can track the complete name/filter/loglevel tuple. This allows the same event name to be specified multiple times but with different parameters. Right now the sessiond does not send the filter string, a new protocol version will be required to do so. But we can prepare for it in the meantime. The agent will continue to use the event names to decide if events should be sent through JNI or not. However, full rules will be useable for other purposes, like the upcoming filter notifications. Signed-off-by: Alexandre Montplaisir <[email protected]>

Java applications can now register to receive notifications of event filtering rules being changed in the tracing session. This can be used to implement application-specific filtering on the Java side, to reduce the amount of events sent through JNI. To do so, they need to implement a IFilterChangeListener and register it to the FilterChangeNotifier. The listener's callbacks will be invoked by the LTTng agent when the tracing session(s) change. A new example file is provided to demo this usage. Signed-off-by: Alexandre Montplaisir <[email protected]>

Signed-off-by: Alexandre Montplaisir <[email protected]>

Update to agent protocol 2.0, which now sends the filter string as part of the "enable event" command. Signed-off-by: Alexandre Montplaisir <[email protected]>

PSRCode · 2015-10-20T21:46:46Z

@alexmonthy what is the status of this ?

ghost · 2015-10-20T22:43:17Z

It's still waiting on lttng/lttng-tools#42 . This patch bumps the agent protocol version to 2.0, and that PR for tools does the corresponding updates.

Observed issue ============== Applications which transitively dlopen() a library which, in turn, dlopen() providers crash when they are compiled with clang or if LTTNG_UST_ALLOCATE_COMPOUND_LITERAL_ON_HEAP is defined. Core was generated by `././myapp.exe'. Program terminated with signal SIGSEGV, Segmentation fault. #0 0x00007fa94f860bc2 in check_event_provider (probe_desc=<optimized out>) at lttng-probes.c:153 153 if (!check_type_provider(field->type)) { [Current thread is 1 (Thread 0x7fa94fcbc740 (LWP 511754))] (gdb) bt #0 0x00007fa94f860bc2 in check_event_provider (probe_desc=<optimized out>) at lttng-probes.c:153 #1 lttng_ust_probe_register (desc=0x7fa94fe9dc80 <lttng_ust__probe_desc___embedded_sys>) at lttng-probes.c:242 #2 0x00007fa94fe9ba3c in lttng_ust__tracepoints__ptrs_destroy () at /usr/include/lttng/tracepoint.h:590 #3 0x00007fa94fedfe2e in call_init () from /lib64/ld-linux-x86-64.so.2 #4 0x00007fa94fedff1c in _dl_init () from /lib64/ld-linux-x86-64.so.2 #5 0x00007fa94fdf7d45 in _dl_catch_exception () from /usr/lib/libc.so.6 #6 0x00007fa94fee420a in dl_open_worker () from /lib64/ld-linux-x86-64.so.2 #7 0x00007fa94fdf7ce8 in _dl_catch_exception () from /usr/lib/libc.so.6 #8 0x00007fa94fee39bb in _dl_open () from /lib64/ld-linux-x86-64.so.2 #9 0x00007fa94fe8d36c in ?? () from /usr/lib/libdl.so.2 #10 0x00007fa94fdf7ce8 in _dl_catch_exception () from /usr/lib/libc.so.6 #11 0x00007fa94fdf7db3 in _dl_catch_error () from /usr/lib/libc.so.6 #12 0x00007fa94fe8db99 in ?? () from /usr/lib/libdl.so.2 #13 0x00007fa94fe8d3f8 in dlopen () from /usr/lib/libdl.so.2 #14 0x00007fa94fecc647 in mon_constructeur () at mylib.cpp:20 #15 0x00007fa94fedfe2e in call_init () from /lib64/ld-linux-x86-64.so.2 #16 0x00007fa94fedff1c in _dl_init () from /lib64/ld-linux-x86-64.so.2 #17 0x00007fa94fdf7d45 in _dl_catch_exception () from /usr/lib/libc.so.6 #18 0x00007fa94fee420a in dl_open_worker () from /lib64/ld-linux-x86-64.so.2 #19 0x00007fa94fdf7ce8 in _dl_catch_exception () from /usr/lib/libc.so.6 #20 0x00007fa94fee39bb in _dl_open () from /lib64/ld-linux-x86-64.so.2 #21 0x00007fa94fe8d36c in ?? () from /usr/lib/libdl.so.2 #22 0x00007fa94fdf7ce8 in _dl_catch_exception () from /usr/lib/libc.so.6 #23 0x00007fa94fdf7db3 in _dl_catch_error () from /usr/lib/libc.so.6 #24 0x00007fa94fe8db99 in ?? () from /usr/lib/libdl.so.2 #25 0x00007fa94fe8d3f8 in dlopen () from /usr/lib/libdl.so.2 #26 0x00005594f478c18c in main () Cause ===== Building tracepoint instrumentation as C++ using clang causes LTTNG_UST_ALLOCATE_COMPOUND_LITERAL_ON_HEAP to be defined due to a compiler version detection problem addressed by another patch. However, building with LTTNG_UST_ALLOCATE_COMPOUND_LITERAL_ON_HEAP defined still results in the crash. When LTTNG_UST_ALLOCATE_COMPOUND_LITERAL_ON_HEAP is defined, the lttng_ust_event_field lttng_ust__event_fields__[...] structure is initialized by dynamically-allocating field structures for the various fields. As the initialization can't be performed statically, it is performed at run-time _after_ the execution of the library constructors has completed. Moreover, the generated initialization function of the provider (lttng_ust__events_init__[...]) is declared as being a library constructor. Hence, this causes it to run before the tracepoint fields structures has a chance to be initialized. This all results in a NULL pointer dereference during the validation of the fields. Solution ======== When building providers as C++, the initialization function is defined as the constructor of a class. This class is, in turn, instantiated in an anonymous namespace. For the purposes of this patch, the use of an anonymous namespace is equivalent to declaring the instance as 'static', but it is preferred in C++11. Known drawbacks =============== None. References ========== A reproducer is available: https://github.com/jgalar/ust-clang-reproducer Problem initially reported on dotnet/runtime's issue tracker: dotnet/runtime#62398 Relevant LTTng-UST issue: https://bugs.lttng.org/issues/1339 Fixes: #1339 Change-Id: I51cfbe74729bd45e2613a30bc8de17e08ea8233d Signed-off-by: Jérémie Galarneau <[email protected]> Signed-off-by: Mathieu Desnoyers <[email protected]>

Eliminate the following deadlock by calling libc close directly when called from within the 2.12 fd tracker locking. The 2.13 locks always need to be taken outside of the 2.12 locks. In the scenario below, Thread 3 (lttng-ust 2.12 listener thread) takes the locks in the wrong order. Thread 3 (Thread 0x7f7679247700 (LWP 621683) "hello-ust"): #0 __lll_lock_wait (futex=futex@entry=0x7f767a392b60 <ust_safe_guard_fd_mutex>, private=0) at lowlevellock.c:52 lttng#1 0x00007f767a39d843 in __GI___pthread_mutex_lock (mutex=0x7f767a392b60 <ust_safe_guard_fd_mutex>) at ../nptl/pthread_mutex_lock.c:80 -> 2.13 locks fd tracker 2.13 lttng#2 0x00007f767a37ff82 in lttng_ust_lock_fd_tracker_orig () at fd-tracker.c:163 2.13 lttng#3 0x00007f767a380b66 in lttng_ust_safe_close_fd_orig (fd=3, close_cb=0x7f767a56b070 <__GI___close>) at fd-tracker.c:385 2.13 lttng#4 0x00007f767a6e5557 in close (fd=3) at lttng-ust-fd.c:101 2.12 lttng#5 0x00007f767a297e7d in ustcomm_connect_unix_sock (pathname=0x7f767a32bc64 <local_apps+36> "/home/compudj/.lttng/lttng-ust-sock-8", timeout=3000) at lttng-ust-comm.c:157 -> 2.12 listener thread locks fd tracker -> 2.12 listener thread locks ust_lock 2.12 lttng#6 0x00007f767a2a1f77 in ust_listener_thread (arg=0x7f767a32bc40 <local_apps>) at lttng-ust-comm.c:1591 lttng#7 0x00007f767a39aea7 in start_thread (arg=<optimized out>) at pthread_create.c:477 lttng#8 0x00007f767a57aaef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 2 (Thread 0x7f7678a46700 (LWP 621682) "hello-ust"): #0 __lll_lock_wait (futex=futex@entry=0x7f767a32f780 <ust_mutex>, private=0) at lowlevellock.c:52 lttng#1 0x00007f767a39d843 in __GI___pthread_mutex_lock (mutex=0x7f767a32f780 <ust_mutex>) at ../nptl/pthread_mutex_lock.c:80 2.12 lttng#2 0x00007f767a29da59 in ust_lock () at lttng-ust-comm.c:167 2.12 lttng#3 0x00007f767a2a1d95 in ust_listener_thread (arg=0x7f767a329be0 <global_apps>) at lttng-ust-comm.c:1558 lttng#4 0x00007f767a39aea7 in start_thread (arg=<optimized out>) at pthread_create.c:477 lttng#5 0x00007f767a57aaef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 1 (Thread 0x7f767a33a040 (LWP 621681) "hello"): #0 __lll_lock_wait (futex=futex@entry=0x7f767a32f720 <ust_safe_guard_fd_mutex>, private=0) at lowlevellock.c:52 lttng#1 0x00007f767a39d843 in __GI___pthread_mutex_lock (mutex=0x7f767a32f720 <ust_safe_guard_fd_mutex>) at ../nptl/pthread_mutex_lock.c:80 -> 2.12 lock fd tracker 2.12 lttng#2 0x00007f767a29c37c in lttng_ust_lock_fd_tracker () at lttng-ust-fd-tracker.c:153 2.12 lttng#3 0x00007f767a29ceba in lttng_ust_safe_close_fd (fd=4, close_cb=0x7f767a56b070 <__GI___close>) at lttng-ust-fd-tracker.c:341 2.13 lttng#4 0x00007f767a380b06 in lttng_ust_safe_close_fd_chain (fd=4, close_cb=0x7f767a56b070 <__GI___close>) at fd-tracker.c:348 2.13 lttng#5 0x00007f767a380b5c in lttng_ust_safe_close_fd_orig (fd=4, close_cb=0x7f767a56b070 <__GI___close>) at fd-tracker.c:379 2.13 lttng#6 0x00007f767a6e5557 in close (fd=4) at lttng-ust-fd.c:101 -> 2.13 lock fd tracker 2.13 lttng#7 0x00007f767a43b5e6 in lttng_ust_elf_destroy (elf=0x55b870f044c0) at elf.c:352 2.13 lttng#8 0x00007f767a3f2797 in get_elf_info (bin_data=0x7ffd5481ef70) at lttng-ust-statedump.c:296 2.13 lttng#9 0x00007f767a3f283f in extract_baddr (bin_data=0x7ffd5481ef70) at lttng-ust-statedump.c:319 2.13 lttng#10 0x00007f767a3f3173 in extract_bin_info_events (info=0x7ffd5481fff0, size=64, _data=0x7ffd54820098) at lttng-ust-statedump.c:518 lttng#11 0x00007f767a5b3ad5 in __GI___dl_iterate_phdr (callback=0x7f767a3f2f5a <extract_bin_info_events>, data=0x7ffd54820098) at dl-iteratephdr.c:75 2.13 lttng#12 0x00007f767a3f32c5 in lttng_ust_dl_update_orig (ip=0x7f767a3cb599 <lttng_ust_ctor+683>) at lttng-ust-statedump.c:574 2.13 lttng#13 0x00007f767a3f33f7 in lttng_ust_statedump_init () at lttng-ust-statedump.c:638 2.13 lttng#14 0x00007f767a3cb599 in lttng_ust_ctor () at lttng-ust-comm.c:2246 2.13 lttng#15 0x00007f767a3ccaad in lttng_ust_after_fork_child (restore_sigset=0x7ffd548207e0) at lttng-ust-comm.c:2577 2.13 lttng#16 0x00007f767a6f687f in fork () at ustfork.c:271 lttng#17 0x000055b8705f1034 in make_child () lttng#18 0x000055b8705daacc in execute_command_internal () lttng#19 0x000055b8705ddcf5 in execute_command () lttng#20 0x000055b8705df951 in ?? () lttng#21 0x000055b8705daf79 in execute_command_internal () lttng#22 0x000055b8705ddcf5 in execute_command () lttng#23 0x000055b8705c49db in reader_loop () lttng#24 0x000055b8705c3668 in main () Getting the state of lttng-ust 2.12 ust_fd_mutex_nest TLS variable is not straightforward, because it is a static variable (internal state). The trick used here is to rely on the "lttng_ust_safe_close_fd" symbol exported by lttng-ust 2.12. When passed fd=-1, with a close_cb which simply returns 0, we can use the resulting return values to determine the current state (zero vs nonzero) of the ust_fd_mutex_nest TLS variable without any side-effect other than temporarily taking/releasing the fd tracker lock when ust_fd_mutex_nest==0. Signed-off-by: Mathieu Desnoyers <[email protected]> Change-Id: I6b95e0fd607abccd67aadf35ec96c19877394b16

Alexandre Montplaisir added 6 commits September 14, 2015 18:06

Turn ILttngAgentResponse into an abstract class

5faea51

This allows defining a default behavior for the getBytes() method. That behavior consists of only returning the integer return code, which is what most (but not all) subclasses use. Signed-off-by: Alexandre Montplaisir <[email protected]>

Document the Java filter notification model

6e6c722

Signed-off-by: Alexandre Montplaisir <[email protected]>

Receive the event filter string in the Java agent

0e37b6c

Update to agent protocol 2.0, which now sends the filter string as part of the "enable event" command. Signed-off-by: Alexandre Montplaisir <[email protected]>

ghost closed this Oct 22, 2015

ghost deleted the for-upstream-java-filter-notifs branch October 22, 2015 21:10

This pull request was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Java filter notification mechanism #11

Java filter notification mechanism #11

ghost commented Sep 1, 2015

ghost commented Sep 1, 2015

ghost commented Sep 2, 2015

ghost commented Sep 11, 2015

ghost commented Sep 13, 2015

compudj commented Sep 14, 2015

ghost commented Sep 14, 2015

compudj commented Sep 14, 2015

ghost commented Sep 14, 2015

ghost commented Sep 14, 2015

PSRCode commented Oct 20, 2015

ghost commented Oct 20, 2015

Java filter notification mechanism #11

Java filter notification mechanism #11

Conversation

ghost commented Sep 1, 2015

ghost commented Sep 1, 2015

ghost commented Sep 2, 2015

ghost commented Sep 11, 2015

ghost commented Sep 13, 2015

compudj commented Sep 14, 2015

ghost commented Sep 14, 2015

compudj commented Sep 14, 2015

ghost commented Sep 14, 2015

ghost commented Sep 14, 2015

PSRCode commented Oct 20, 2015

ghost commented Oct 20, 2015