[lttng-dev] Odd behaviour of lttng 2.0 kernel event listing

[Thibault, Daniel]

> This is very odd...
>
> The "DEBUG1: SIGCHLD catched [in sighandler() at lttng.c:179]" shows you that
> when this signal is caught by the lttng client, it means that the session daemon
> is ready hence the lttng modules are loaded for sure. The session daemon send
> this signal only when it's ready to receive commands.
>
> I think I have a 2.6.38 kernel hanging around somewhere. I'll try to reproduce
> this problem.
>
> In the meantime, change the lttng client to exec the session daemon in verbose mode:
> diff --git a/src/bin/lttng/lttng.c b/src/bin/lttng/lttng.c
> [...]
> -               execlp(pathname, "lttng-sessiond", "--sig-parent", "--quiet", NULL);
> +               execlp(pathname, "lttng-sessiond", "--sig-parent", "-vvv", NULL);
> [...]
> And send us the session daemon debug output.

$ sudo lttng -v list -k
Spawning a session daemon
DEBUG3: Creating LTTng run directory: /var/run/lttng [in create_lttng_rundir() at main.c:4087]
DEBUG2: Kernel consumer err path: /var/run/lttng/kconsumerd/error [in main() at main.c:4312]
DEBUG2: Kernel consumer cmd path: /var/run/lttng/kconsumerd/command [in main() at main.c:4314]
DEBUG1: Client socket path /var/run/lttng/client-lttng-sessiond [in main() at main.c:4357]
DEBUG1: Application socket path /var/run/lttng/apps-lttng-sessiond [in main() at main.c:4358]
DEBUG1: LTTng run directory path: /var/run/lttng [in main() at main.c:4359]
DEBUG2: UST consumer 32 bits err path: /var/run/lttng/ustconsumerd32/error [in main() at main.c:4368]
DEBUG2: UST consumer 32 bits cmd path: /var/run/lttng/ustconsumerd32/command [in main() at main.c:4370]
DEBUG2: UST consumer 64 bits err path: /var/run/lttng/ustconsumerd64/error [in main() at main.c:4379]
DEBUG2: UST consumer 64 bits cmd path: /var/run/lttng/ustconsumerd64/command [in main() at main.c:4381]
DEBUG2: Creating consumer directory: /var/run/lttng/kconsumerd [in set_consumer_sockets() at main.c:4129]
DEBUG1: Got debugfs path : /sys/kernel/debug [in init_kernel_tracer() at main.c:1790]
DEBUG1: Modprobe successfully lttng-ftrace [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully lttng-kprobes [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully lttng-kretprobes [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully lib-ring-buffer [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully ltt-relay [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully ltt-ring-buffer-client-discard [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully ltt-ring-buffer-client-overwrite [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully ltt-ring-buffer-metadata-client [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully ltt-ring-buffer-client-mmap-discard [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully ltt-ring-buffer-client-mmap-overwrite [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully ltt-ring-buffer-metadata-mmap-client [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully lttng-probe-lttng [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully lttng-types [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully lttng-probe-block [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully lttng-probe-irq [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully lttng-probe-kvm [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Modprobe successfully lttng-probe-sched [in modprobe_kernel_modules() at main.c:1732]
DEBUG1: Kernel tracer fd 6 [in init_kernel_tracer() at main.c:1833]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd64 [in set_consumer_sockets() at main.c:4129]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd32 [in set_consumer_sockets() at main.c:4129]
DEBUG1: Signal handler set for SIGTERM, SIGPIPE and SIGINT [in set_signal_handler() at main.c:4220]
DEBUG1: All permissions are set [in set_permissions() at main.c:4058]
DEBUG3: Created hashtable size 4 at 0xf8c630 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0xf8c8f0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: epoll set max size is 206581 [in compat_epoll_set_max_size() at compat/compat-epoll.c:217]
DEBUG1: Thread manage kernel started [in thread_manage_kernel() at main.c:828]
DEBUG1: Updating kernel poll set [in update_kernel_poll() at main.c:706]
DEBUG1: Thread kernel polling on 2 fds [in thread_manage_kernel() at main.c:857]
DEBUG1: [thread] Manage application started [in thread_manage_apps() at main.c:1085]
DEBUG1: Apps thread polling on 2 fds [in thread_manage_apps() at main.c:1106]
DEBUG1: [thread] Manage application registration started [in thread_registration_apps() at main.c:1286]
DEBUG1: Notifying applications of session daemon state: 1 [in notify_ust_apps() at main.c:645]
DEBUG1: Got the wait shm fd 18 [in get_wait_shm() at shm.c:113]
DEBUG1: Futex wait update active 1 [in futex_wait_update() at futex.c:63]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1317]
DEBUG1: [thread] Dispatch UST command started [in thread_dispatch_ust_registration() at main.c:1218]
DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:74]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1228]
DEBUG1: [thread] Manage client started [in thread_manage_clients() at main.c:3629]
DEBUG1: SIGCHLD catched [in sighandler() at lttng.c:179]
DEBUG1: Getting kernel tracing events [in list_kernel_events() at commands/list.c:277]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3661]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3691]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3726]
DEBUG1: Processing client command 14 [in process_client_msg() at main.c:3212]
DEBUG1: Kernel list events done (51 events) [in kernel_list_events() at kernel.c:600]
DEBUG1: Sending response (size: 41224, retcode: Success) [in thread_manage_clients() at main.c:3760]
Kernel events:
-------------
      sched_kthread_stop (type: tracepoint)
      [...]
      kvm_msi_set_irq (type: tracepoint)
       (type: tracepoint) [disabled]
      [...]
       (type: tracepoint) [disabled]

DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:492]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3661]

Daniel U. Thibault
R & D pour la défense Canada - Valcartier (RDDC Valcartier) / Defence R&D Canada - Valcartier (DRDC Valcartier)
Système de systèmes (SdS) / System of Systems (SoS)
Solutions informatiques et expérimentations (SIE) / Computing Solutions and Experimentations (CSE)
2459 Boul. Pie XI Nord
Québec, QC  G3J 1X5
CANADA
Vox : (418) 844-4000 x4245
Fax : (418) 844-4538
NAC: 918V QSDJ
Gouvernement du Canada / Government of Canada
<http://www.valcartier.drdc-rddc.gc.ca/>